From f114cab45e75987eaea09aa54c388501ebe4b94e Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 16 Mar 2026 08:40:18 +0000 Subject: [PATCH 01/10] Initial plan From 05136a83a0ad4df539046051a180f9addd634687 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 16 Mar 2026 08:54:48 +0000 Subject: [PATCH 02/10] Add log levels, stat events, FAIL_CHECK assert helpers, and Catch2 log consumer - Add PlexdbLogLevel enum (TRACE/DEBUG/INFO/WARN/ERROR) and PLEXDB_LOG_STAT event to log_abi.h - Update plexdb::log module with Level enum, level-aware fire_message, fire_stat - Update objstore log to use appropriate log levels (Debug for parse, Error for errors) - Change FAIL to FAIL_CHECK in assert helpers so tests continue after failures - Add Catch2 log consumer helpers that route all logs to UNSCOPED_INFO - Update log_file plugin to handle log levels and stat events - Add tests for log levels and fire_stat Co-authored-by: patricklbell <46551885+patricklbell@users.noreply.github.com> --- objstore/CMakeLists.txt | 1 + objstore/log/log.cpp | 2 + objstore/plugins/log_file/log_file_plugin.cpp | 30 +++++- objstore/test/assert_helpers.test.cpp | 1 - objstore/test/log_consumer.test.cpp | 94 ++++++++++++++++++ plexdb/CMakeLists.txt | 5 + plexdb/log/log.cppm | 44 ++++++++- plexdb/log/log.test.cpp | 95 +++++++++++++++++++ plexdb/log/log_abi.h | 18 +++- plexdb/test/assert_helpers.test.cpp | 2 +- plexdb/test/log_consumer.test.cpp | 94 ++++++++++++++++++ 11 files changed, 379 insertions(+), 7 deletions(-) create mode 100644 objstore/test/log_consumer.test.cpp create mode 100644 plexdb/log/log.test.cpp create mode 100644 plexdb/test/log_consumer.test.cpp diff --git a/objstore/CMakeLists.txt b/objstore/CMakeLists.txt index f2815f1..a4a7466 100644 --- a/objstore/CMakeLists.txt +++ b/objstore/CMakeLists.txt @@ -195,6 +195,7 @@ if(BUILD_TESTS) target_include_directories(objstore_tests PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}/../macros + ${CMAKE_CURRENT_SOURCE_DIR}/../plexdb/log ) target_link_libraries(objstore_tests diff --git a/objstore/log/log.cpp b/objstore/log/log.cpp index 37a4362..96be0e1 100644 --- a/objstore/log/log.cpp +++ b/objstore/log/log.cpp @@ -9,6 +9,7 @@ namespace objstore::log { void cql_parse_query(plexdb::String8 query) { plexdb::log::fire_message( producer.id, + plexdb::log::Level::Debug, reinterpret_cast(query.data), query.length ); @@ -17,6 +18,7 @@ namespace objstore::log { void cql_parse_error(const char* text, plexdb::U64 len) { plexdb::log::fire_message( producer.id, + plexdb::log::Level::Error, text, len ); diff --git a/objstore/plugins/log_file/log_file_plugin.cpp b/objstore/plugins/log_file/log_file_plugin.cpp index 6352bf2..9d30dac 100644 --- a/objstore/plugins/log_file/log_file_plugin.cpp +++ b/objstore/plugins/log_file/log_file_plugin.cpp @@ -63,8 +63,9 @@ struct State { producers[id] = name; } - void on_message(uint32_t producer_id, const char* text, size_t len) { - std::time_t t = std::time(nullptr); + void on_message(uint32_t producer_id, uint32_t level, const char* text, size_t len) { + static constexpr const char* level_tags[] = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR"}; + const char* tag = (level < 5) ? level_tags[level] : "???"; std::lock_guard guard(mtx); std::string line = ""; @@ -73,6 +74,9 @@ struct State { line += '[' + it->second + "] "; } line += '[' + current_local_datetime() + "] "; + line += '['; + line += tag; + line += "] "; line.append(text, len); buffer.push_back(std::move(line)); @@ -81,6 +85,21 @@ struct State { } } + void on_stat(uint32_t producer_id, uint32_t stat_id, int64_t value) { + std::lock_guard guard(mtx); + std::string line = ""; + auto it = producers.find(producer_id); + if (it != producers.end()) { + line += '[' + it->second + "] "; + } + line += '[' + current_local_datetime() + "] "; + line += "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); + buffer.push_back(std::move(line)); + if (buffer.size() >= batch) { + flush_locked(); + } + } + void flush() { std::lock_guard guard(mtx); flush_locked(); @@ -114,9 +133,16 @@ void on_event(const PlexdbLogEvent* event, void* ctx) { case PLEXDB_LOG_MESSAGE:{ state->on_message( event->message.producer_id, + event->message.level, event->message.text, event->message.text_len); }break; + case PLEXDB_LOG_STAT:{ + state->on_stat( + event->stat.producer_id, + event->stat.stat_id, + event->stat.value); + }break; } } diff --git a/objstore/test/assert_helpers.test.cpp b/objstore/test/assert_helpers.test.cpp index e76a6af..cdde5e9 100644 --- a/objstore/test/assert_helpers.test.cpp +++ b/objstore/test/assert_helpers.test.cpp @@ -13,7 +13,6 @@ import plexdb.base; // 1. Record the failure with FAIL_CHECK (non-throwing). // 2. If PLEXDB_TEST_SCOPE() was used, longjmp back to exit the test case. // ============================================================================ - namespace { struct AssertRecovery { diff --git a/objstore/test/log_consumer.test.cpp b/objstore/test/log_consumer.test.cpp new file mode 100644 index 0000000..b9974d1 --- /dev/null +++ b/objstore/test/log_consumer.test.cpp @@ -0,0 +1,94 @@ +#include +#include +#include +#include +#include "log_abi.h" + +#include +#include +#include + +namespace { + +struct LogBuffer { + std::vector entries; + std::mutex mtx; + bool active = false; + + void clear() { + std::lock_guard g(mtx); + entries.clear(); + } + + void push(const char* level, const char* text, size_t len) { + std::lock_guard g(mtx); + if (!active) return; + std::string entry = "["; + entry += level; + entry += "] "; + entry.append(text, len); + entries.push_back(std::move(entry)); + UNSCOPED_INFO(entries.back()); + } + + void push_stat(uint32_t stat_id, int64_t value) { + std::lock_guard g(mtx); + if (!active) return; + std::string entry = "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); + entries.push_back(std::move(entry)); + UNSCOPED_INFO(entries.back()); + } +}; + +LogBuffer g_log_buffer; + +const char* level_str(uint32_t lvl) { + switch (lvl) { + case PLEXDB_LOG_TRACE: return "TRACE"; + case PLEXDB_LOG_DEBUG: return "DEBUG"; + case PLEXDB_LOG_INFO: return "INFO"; + case PLEXDB_LOG_WARN: return "WARN"; + case PLEXDB_LOG_ERROR: return "ERROR"; + default: return "???"; + } +} + +void on_log_event(const PlexdbLogEvent* event, void* /*ctx*/) { + switch (event->type) { + case PLEXDB_LOG_MESSAGE: + g_log_buffer.push( + level_str(event->message.level), + event->message.text, + event->message.text_len); + break; + case PLEXDB_LOG_STAT: + g_log_buffer.push_stat( + event->stat.stat_id, + event->stat.value); + break; + default: + break; + } +} + +struct LogListener : Catch::EventListenerBase { + using EventListenerBase::EventListenerBase; + + void testCaseStarting(Catch::TestCaseInfo const&) override { + g_log_buffer.active = true; + g_log_buffer.clear(); + } + void testCaseEnded(Catch::TestCaseStats const&) override { + g_log_buffer.active = false; + g_log_buffer.clear(); + } +}; +CATCH_REGISTER_LISTENER(LogListener) + +struct LogConsumerInstaller { + LogConsumerInstaller() { plexdb_log_register_consumer(on_log_event, nullptr); } + ~LogConsumerInstaller() { plexdb_log_unregister_consumer(on_log_event, nullptr); } +}; +static LogConsumerInstaller g_install; + +} // namespace diff --git a/plexdb/CMakeLists.txt b/plexdb/CMakeLists.txt index 0eea9b3..03ea733 100644 --- a/plexdb/CMakeLists.txt +++ b/plexdb/CMakeLists.txt @@ -141,6 +141,11 @@ if(BUILD_TESTS) "${CMAKE_CURRENT_SOURCE_DIR}/**/*.test.cpp" ) target_sources(plexdb_tests PRIVATE ${PLEXDB_TEST_SOURCES}) + + target_include_directories(plexdb_tests PRIVATE + ${CMAKE_CURRENT_SOURCE_DIR}/log + ) + target_link_libraries(plexdb_tests PRIVATE plexdb::plexdb diff --git a/plexdb/log/log.cppm b/plexdb/log/log.cppm index bbeeb1c..28e46e7 100644 --- a/plexdb/log/log.cppm +++ b/plexdb/log/log.cppm @@ -17,6 +17,28 @@ export namespace plexdb::log { false; #endif + // ======================================================================== + // log levels + // ======================================================================== + enum class Level : uint32_t { + Trace = PLEXDB_LOG_TRACE, + Debug = PLEXDB_LOG_DEBUG, + Info = PLEXDB_LOG_INFO, + Warn = PLEXDB_LOG_WARN, + Error = PLEXDB_LOG_ERROR, + }; + + inline constexpr const char* to_str(Level lvl) { + switch (lvl) { + case Level::Trace: return "TRACE"; + case Level::Debug: return "DEBUG"; + case Level::Info: return "INFO"; + case Level::Warn: return "WARN"; + case Level::Error: return "ERROR"; + } + return "???"; + } + // ======================================================================== // producer // registers itself on construction, deregisters on destruction. @@ -44,11 +66,29 @@ export namespace plexdb::log { // messaging // zero-overhead when disabled via if constexpr. // ======================================================================== - inline void fire_message(uint32_t producer_id, const char* text, size_t text_len) { + inline void fire_message(uint32_t producer_id, Level level, const char* text, size_t text_len) { if constexpr (enabled) { PlexdbLogEvent e{}; e.type = PLEXDB_LOG_MESSAGE; - e.message = {producer_id, 0, text, text_len}; + e.message = {producer_id, static_cast(level), text, text_len}; + dispatch(e); + } + } + + inline void fire_message(uint32_t producer_id, const char* text, size_t text_len) { + fire_message(producer_id, Level::Info, text, text_len); + } + + // ======================================================================== + // stats + // zero-overhead structured numeric events for realtime metrics. + // no string formatting overhead — consumers read the value directly. + // ======================================================================== + inline void fire_stat(uint32_t producer_id, uint32_t stat_id, int64_t value) { + if constexpr (enabled) { + PlexdbLogEvent e{}; + e.type = PLEXDB_LOG_STAT; + e.stat = {producer_id, stat_id, value}; dispatch(e); } } diff --git a/plexdb/log/log.test.cpp b/plexdb/log/log.test.cpp new file mode 100644 index 0000000..4190c23 --- /dev/null +++ b/plexdb/log/log.test.cpp @@ -0,0 +1,95 @@ +#include +#include "log_abi.h" + +import plexdb.log; + +using namespace plexdb::log; + +TEST_CASE("log level to_str", "[plexdb.log]") { + CHECK(to_str(Level::Trace)[0] == 'T'); + CHECK(to_str(Level::Debug)[0] == 'D'); + CHECK(to_str(Level::Info)[0] == 'I'); + CHECK(to_str(Level::Warn)[0] == 'W'); + CHECK(to_str(Level::Error)[0] == 'E'); +} + +namespace { + struct TestConsumer { + unsigned message_count = 0; + unsigned stat_count = 0; + uint32_t last_level = 0; + int64_t last_stat_val = 0; + uint32_t last_stat_id = 0; + }; + + void test_on_event(const PlexdbLogEvent* event, void* ctx) { + auto* c = static_cast(ctx); + switch (event->type) { + case PLEXDB_LOG_MESSAGE: + c->message_count++; + c->last_level = event->message.level; + break; + case PLEXDB_LOG_STAT: + c->stat_count++; + c->last_stat_id = event->stat.stat_id; + c->last_stat_val = event->stat.value; + break; + default: + break; + } + } +} + +TEST_CASE("fire_message with log level", "[plexdb.log]") { + if constexpr (!enabled) { + SKIP("logging disabled"); + } + + TestConsumer tc{}; + plexdb_log_register_consumer(test_on_event, &tc); + + Producer p{"test_level"}; + + SECTION("default level is Info") { + fire_message(p.id, "hello", 5); + CHECK(tc.message_count == 1); + CHECK(tc.last_level == static_cast(Level::Info)); + } + + SECTION("explicit Error level") { + fire_message(p.id, Level::Error, "fail", 4); + CHECK(tc.message_count == 1); + CHECK(tc.last_level == static_cast(Level::Error)); + } + + SECTION("explicit Trace level") { + fire_message(p.id, Level::Trace, "trace", 5); + CHECK(tc.message_count == 1); + CHECK(tc.last_level == static_cast(Level::Trace)); + } + + plexdb_log_unregister_consumer(test_on_event, &tc); +} + +TEST_CASE("fire_stat delivers structured metrics", "[plexdb.log]") { + if constexpr (!enabled) { + SKIP("logging disabled"); + } + + TestConsumer tc{}; + plexdb_log_register_consumer(test_on_event, &tc); + + Producer p{"test_stat"}; + + fire_stat(p.id, 42, 1000); + CHECK(tc.stat_count == 1); + CHECK(tc.last_stat_id == 42); + CHECK(tc.last_stat_val == 1000); + + fire_stat(p.id, 7, -99); + CHECK(tc.stat_count == 2); + CHECK(tc.last_stat_id == 7); + CHECK(tc.last_stat_val == -99); + + plexdb_log_unregister_consumer(test_on_event, &tc); +} diff --git a/plexdb/log/log_abi.h b/plexdb/log/log_abi.h index 477e71a..17b5729 100644 --- a/plexdb/log/log_abi.h +++ b/plexdb/log/log_abi.h @@ -10,9 +10,18 @@ extern "C" { // ============================================================================ // data types // ============================================================================ +typedef enum PlexdbLogLevel : uint32_t { + PLEXDB_LOG_TRACE = 0, + PLEXDB_LOG_DEBUG = 1, + PLEXDB_LOG_INFO = 2, + PLEXDB_LOG_WARN = 3, + PLEXDB_LOG_ERROR = 4, +} PlexdbLogLevel; + typedef enum PlexdbLogEventType : uint32_t { PLEXDB_LOG_PRODUCER_REGISTERED = 1, // producer announces itself PLEXDB_LOG_MESSAGE = 2, // generic string message + PLEXDB_LOG_STAT = 3, // structured numeric stat } PlexdbLogEventType; typedef struct { @@ -22,11 +31,17 @@ typedef struct { typedef struct { uint32_t producer_id; - uint32_t _pad; // @padding + uint32_t level; // PlexdbLogLevel const char* text; size_t text_len; } PlexdbLogMessage; +typedef struct { + uint32_t producer_id; + uint32_t stat_id; + int64_t value; +} PlexdbLogStat; + // @note fat struct with a type tag and union payload typedef struct { uint32_t type; // PlexdbLogEventType @@ -34,6 +49,7 @@ typedef struct { union { PlexdbLogProducerRegistered producer_registered; PlexdbLogMessage message; + PlexdbLogStat stat; }; } PlexdbLogEvent; diff --git a/plexdb/test/assert_helpers.test.cpp b/plexdb/test/assert_helpers.test.cpp index 4f04b03..852a43d 100644 --- a/plexdb/test/assert_helpers.test.cpp +++ b/plexdb/test/assert_helpers.test.cpp @@ -3,7 +3,7 @@ import plexdb.base; inline void catch2_assert_handler(const char* msg, const char* file_name, const char* function_name, unsigned line_number) { - FAIL("Assert failed \"" << msg << "\" at " << function_name << " in " << file_name << ":" << line_number); + FAIL_CHECK("Assert failed \"" << msg << "\" at " << function_name << " in " << file_name << ":" << line_number); } struct AssertHandlerInstaller { diff --git a/plexdb/test/log_consumer.test.cpp b/plexdb/test/log_consumer.test.cpp new file mode 100644 index 0000000..b9974d1 --- /dev/null +++ b/plexdb/test/log_consumer.test.cpp @@ -0,0 +1,94 @@ +#include +#include +#include +#include +#include "log_abi.h" + +#include +#include +#include + +namespace { + +struct LogBuffer { + std::vector entries; + std::mutex mtx; + bool active = false; + + void clear() { + std::lock_guard g(mtx); + entries.clear(); + } + + void push(const char* level, const char* text, size_t len) { + std::lock_guard g(mtx); + if (!active) return; + std::string entry = "["; + entry += level; + entry += "] "; + entry.append(text, len); + entries.push_back(std::move(entry)); + UNSCOPED_INFO(entries.back()); + } + + void push_stat(uint32_t stat_id, int64_t value) { + std::lock_guard g(mtx); + if (!active) return; + std::string entry = "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); + entries.push_back(std::move(entry)); + UNSCOPED_INFO(entries.back()); + } +}; + +LogBuffer g_log_buffer; + +const char* level_str(uint32_t lvl) { + switch (lvl) { + case PLEXDB_LOG_TRACE: return "TRACE"; + case PLEXDB_LOG_DEBUG: return "DEBUG"; + case PLEXDB_LOG_INFO: return "INFO"; + case PLEXDB_LOG_WARN: return "WARN"; + case PLEXDB_LOG_ERROR: return "ERROR"; + default: return "???"; + } +} + +void on_log_event(const PlexdbLogEvent* event, void* /*ctx*/) { + switch (event->type) { + case PLEXDB_LOG_MESSAGE: + g_log_buffer.push( + level_str(event->message.level), + event->message.text, + event->message.text_len); + break; + case PLEXDB_LOG_STAT: + g_log_buffer.push_stat( + event->stat.stat_id, + event->stat.value); + break; + default: + break; + } +} + +struct LogListener : Catch::EventListenerBase { + using EventListenerBase::EventListenerBase; + + void testCaseStarting(Catch::TestCaseInfo const&) override { + g_log_buffer.active = true; + g_log_buffer.clear(); + } + void testCaseEnded(Catch::TestCaseStats const&) override { + g_log_buffer.active = false; + g_log_buffer.clear(); + } +}; +CATCH_REGISTER_LISTENER(LogListener) + +struct LogConsumerInstaller { + LogConsumerInstaller() { plexdb_log_register_consumer(on_log_event, nullptr); } + ~LogConsumerInstaller() { plexdb_log_unregister_consumer(on_log_event, nullptr); } +}; +static LogConsumerInstaller g_install; + +} // namespace From 9882dc70870a960b0711dfd0b03268e93c61199f Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 16 Mar 2026 08:57:25 +0000 Subject: [PATCH 03/10] Address code review: default switch case, array bounds safety, init order docs Co-authored-by: patricklbell <46551885+patricklbell@users.noreply.github.com> --- .github/instructions/tests.instructions.md | 10 +++++++++- AGENTS.md | 10 +++++++++- objstore/plugins/log_file/log_file_plugin.cpp | 3 ++- objstore/test/log_consumer.test.cpp | 2 ++ plexdb/log/log.cppm | 2 +- plexdb/test/log_consumer.test.cpp | 2 ++ 6 files changed, 25 insertions(+), 4 deletions(-) diff --git a/.github/instructions/tests.instructions.md b/.github/instructions/tests.instructions.md index e7aa64d..c1cec0a 100644 --- a/.github/instructions/tests.instructions.md +++ b/.github/instructions/tests.instructions.md @@ -29,10 +29,18 @@ TEST_CASE("descriptive name", "[tag]") { ``` ## Running Tests -- Build: `ninja -C build` +- Build: `cmake -B build -G Ninja -DBUILD_TESTS=ON -DPLEXDB_LOG_ENABLED=ON -DPLEXDB_DEBUG=ON && ninja -C build` - Run all: `./build/plexdb/plexdb_tests --skip-benchmarks` or `./build/objstore/objstore_tests --skip-benchmarks` - Run specific tags: `./build/objstore/objstore_tests --skip-benchmarks "[tagname]"` +## Debugging Test Failures +- Build with `-DPLEXDB_LOG_ENABLED=ON` so log messages appear in failing tests. +- All `plexdb::log` messages are routed to Catch2 `UNSCOPED_INFO` by the test log consumer (`test/log_consumer.test.cpp`). When a test fails, all log messages emitted during that test case are printed alongside the failure. +- To add diagnostic logging in production code, use `plexdb::log::fire_message(producer.id, Level::Debug, text, len)`. This is zero-overhead when logging is disabled at build time. +- For numeric metrics without string formatting overhead, use `plexdb::log::fire_stat(producer.id, stat_id, value)`. +- Custom log consumers can be registered via the plugin ABI (`plexdb_log_register_consumer` in `plexdb/log/log_abi.h`). Write a consumer to filter by producer ID, log level, or stat ID. +- Parse errors are reported via `UNSCOPED_INFO` through `objstore/test/parsers_error_reporter.helper.cppm` and also through the log system (`objstore::log::cql_parse_error` at `Level::Error`). + ## Benchmarks - Catch2 supports benchmarks but use them sparingly - Always use `--skip-benchmarks` for normal test runs diff --git a/AGENTS.md b/AGENTS.md index 0b1faf4..5190614 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -14,4 +14,12 @@ ## Testing - Tests use [Catch2](https://github.com/catchorg/Catch2/blob/devel/docs/). Create tests for your changes. -- Test executables: `build/plexdb/plexdb_tests`, `build/objstore/objstore_tests`. Use `--skip-benchmarks` for normal runs. \ No newline at end of file +- Test executables: `build/plexdb/plexdb_tests`, `build/objstore/objstore_tests`. Use `--skip-benchmarks` for normal runs. + +## Logging & debugging test failures +- Build with `-DPLEXDB_LOG_ENABLED=ON` to enable the structured logging system. +- All log messages are routed to Catch2's `UNSCOPED_INFO` via the test log consumer (`test/log_consumer.test.cpp`). They appear automatically in the output of any failing test case. +- The log system uses levels: `Trace`, `Debug`, `Info`, `Warn`, `Error` (see `plexdb::log::Level`). +- To add diagnostic logging, create a `plexdb::log::Producer` and call `plexdb::log::fire_message(producer.id, Level::Debug, text, len)`. +- For structured numeric metrics use `plexdb::log::fire_stat(producer.id, stat_id, value)` — no string formatting overhead. +- The plugin system (`plexdb/log/log_abi.h`) allows custom consumers. Register via `plexdb_log_register_consumer` to filter or redirect logs. See `objstore/plugins/log_file/log_file_plugin.cpp` for a reference plugin. \ No newline at end of file diff --git a/objstore/plugins/log_file/log_file_plugin.cpp b/objstore/plugins/log_file/log_file_plugin.cpp index 9d30dac..16cd3db 100644 --- a/objstore/plugins/log_file/log_file_plugin.cpp +++ b/objstore/plugins/log_file/log_file_plugin.cpp @@ -65,7 +65,8 @@ struct State { void on_message(uint32_t producer_id, uint32_t level, const char* text, size_t len) { static constexpr const char* level_tags[] = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR"}; - const char* tag = (level < 5) ? level_tags[level] : "???"; + constexpr size_t n_levels = sizeof(level_tags) / sizeof(level_tags[0]); + const char* tag = (level < n_levels) ? level_tags[level] : "???"; std::lock_guard guard(mtx); std::string line = ""; diff --git a/objstore/test/log_consumer.test.cpp b/objstore/test/log_consumer.test.cpp index b9974d1..1940b56 100644 --- a/objstore/test/log_consumer.test.cpp +++ b/objstore/test/log_consumer.test.cpp @@ -85,6 +85,8 @@ struct LogListener : Catch::EventListenerBase { }; CATCH_REGISTER_LISTENER(LogListener) +// @note Static init order: consumer only sees messages fired after registration. +// Producer catch-up IS replayed (see log_abi.h load-order contract). struct LogConsumerInstaller { LogConsumerInstaller() { plexdb_log_register_consumer(on_log_event, nullptr); } ~LogConsumerInstaller() { plexdb_log_unregister_consumer(on_log_event, nullptr); } diff --git a/plexdb/log/log.cppm b/plexdb/log/log.cppm index 28e46e7..be57c52 100644 --- a/plexdb/log/log.cppm +++ b/plexdb/log/log.cppm @@ -35,8 +35,8 @@ export namespace plexdb::log { case Level::Info: return "INFO"; case Level::Warn: return "WARN"; case Level::Error: return "ERROR"; + default: return "???"; } - return "???"; } // ======================================================================== diff --git a/plexdb/test/log_consumer.test.cpp b/plexdb/test/log_consumer.test.cpp index b9974d1..1940b56 100644 --- a/plexdb/test/log_consumer.test.cpp +++ b/plexdb/test/log_consumer.test.cpp @@ -85,6 +85,8 @@ struct LogListener : Catch::EventListenerBase { }; CATCH_REGISTER_LISTENER(LogListener) +// @note Static init order: consumer only sees messages fired after registration. +// Producer catch-up IS replayed (see log_abi.h load-order contract). struct LogConsumerInstaller { LogConsumerInstaller() { plexdb_log_register_consumer(on_log_event, nullptr); } ~LogConsumerInstaller() { plexdb_log_unregister_consumer(on_log_event, nullptr); } From 942c62c85fb4e024b3e15cde380d363bcd18426e Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 16 Mar 2026 09:30:25 +0000 Subject: [PATCH 04/10] Fix assert handler, add stat metadata event, stat plugin, and Python graphing script - Revert FAIL_CHECK back to FAIL in assert handlers so assertions stop the test case (preventing continued execution with corrupted state) - Remove noexcept from assert_true/assert_true_always so the assert handler can interact with the test framework (noexcept was incompatible with Catch2 FAIL) - Add PLEXDB_LOG_STAT_META event type to log ABI for stat metadata (maps producer_id + stat_id to a human-readable name) - Add fire_stat_meta() to plexdb::log module - Create log_stat plugin that writes stat events to a parseable text file - Create extra/plot_stats.py script to graph stat data using matplotlib - Update log_file plugin and test log consumers to handle stat metadata - Add tests for fire_stat_meta - Update AGENTS.md and test instructions with stat metadata documentation Co-authored-by: patricklbell <46551885+patricklbell@users.noreply.github.com> --- .github/instructions/tests.instructions.md | 2 + .gitignore | 1 + AGENTS.md | 4 +- extra/__pycache__/plot_stats.cpython-312.pyc | Bin 0 -> 5236 bytes extra/plot_stats.py | 109 ++++++++++++++++++ objstore/CMakeLists.txt | 13 +++ objstore/plugins/log_file/log_file_plugin.cpp | 32 ++++- objstore/plugins/log_stat/log_stat_plugin.cpp | 105 +++++++++++++++++ objstore/test/log_consumer.test.cpp | 26 ++++- plexdb/base/types.cppm | 9 +- plexdb/log/log.cppm | 9 ++ plexdb/log/log.test.cpp | 36 ++++++ plexdb/log/log_abi.h | 8 ++ plexdb/test/assert_helpers.test.cpp | 2 +- plexdb/test/log_consumer.test.cpp | 26 ++++- 15 files changed, 362 insertions(+), 20 deletions(-) create mode 100644 extra/__pycache__/plot_stats.cpython-312.pyc create mode 100644 extra/plot_stats.py create mode 100644 objstore/plugins/log_stat/log_stat_plugin.cpp diff --git a/.github/instructions/tests.instructions.md b/.github/instructions/tests.instructions.md index c1cec0a..97a1aa4 100644 --- a/.github/instructions/tests.instructions.md +++ b/.github/instructions/tests.instructions.md @@ -38,7 +38,9 @@ TEST_CASE("descriptive name", "[tag]") { - All `plexdb::log` messages are routed to Catch2 `UNSCOPED_INFO` by the test log consumer (`test/log_consumer.test.cpp`). When a test fails, all log messages emitted during that test case are printed alongside the failure. - To add diagnostic logging in production code, use `plexdb::log::fire_message(producer.id, Level::Debug, text, len)`. This is zero-overhead when logging is disabled at build time. - For numeric metrics without string formatting overhead, use `plexdb::log::fire_stat(producer.id, stat_id, value)`. +- Register stat metadata with `plexdb::log::fire_stat_meta(producer.id, stat_id, "name")` so consumers display human-readable stat names on failure. - Custom log consumers can be registered via the plugin ABI (`plexdb_log_register_consumer` in `plexdb/log/log_abi.h`). Write a consumer to filter by producer ID, log level, or stat ID. +- The stat plugin (`objstore/plugins/log_stat/log_stat_plugin.cpp`) writes stat events to a file. Graph them with `python extra/plot_stats.py plexdb.stats`. - Parse errors are reported via `UNSCOPED_INFO` through `objstore/test/parsers_error_reporter.helper.cppm` and also through the log system (`objstore::log::cql_parse_error` at `Level::Error`). ## Benchmarks diff --git a/.gitignore b/.gitignore index 3122a80..842b4d9 100644 --- a/.gitignore +++ b/.gitignore @@ -4,6 +4,7 @@ build/ out/ _codeql_detected_source_root *.db +*.stats objstore.pid **/.venv **/node_modules \ No newline at end of file diff --git a/AGENTS.md b/AGENTS.md index 5190614..4b86255 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -22,4 +22,6 @@ - The log system uses levels: `Trace`, `Debug`, `Info`, `Warn`, `Error` (see `plexdb::log::Level`). - To add diagnostic logging, create a `plexdb::log::Producer` and call `plexdb::log::fire_message(producer.id, Level::Debug, text, len)`. - For structured numeric metrics use `plexdb::log::fire_stat(producer.id, stat_id, value)` — no string formatting overhead. -- The plugin system (`plexdb/log/log_abi.h`) allows custom consumers. Register via `plexdb_log_register_consumer` to filter or redirect logs. See `objstore/plugins/log_file/log_file_plugin.cpp` for a reference plugin. \ No newline at end of file +- Register stat metadata with `plexdb::log::fire_stat_meta(producer.id, stat_id, "name")` so consumers can map stat IDs to human-readable names. +- The plugin system (`plexdb/log/log_abi.h`) allows custom consumers. Register via `plexdb_log_register_consumer` to filter or redirect logs. See `objstore/plugins/log_file/log_file_plugin.cpp` for a reference plugin. +- The stat plugin (`objstore/plugins/log_stat/log_stat_plugin.cpp`) writes stat events to a file. Graph them with `python extra/plot_stats.py plexdb.stats`. \ No newline at end of file diff --git a/extra/__pycache__/plot_stats.cpython-312.pyc b/extra/__pycache__/plot_stats.cpython-312.pyc new file mode 100644 index 0000000000000000000000000000000000000000..77ed8abbbd7bf46960b35a5d61db7a62537dbc81 GIT binary patch literal 5236 zcmcH-TTC3+_0DTwv&$||1Bso%*oKW^iG}kbwi|4~U||;pyNao;?XWW}vz~o;W)_>( zY>TBtSrR1HNhH>_qima~!m>Y7sZ#P8DXrS7i3)+lo2etYt$+9rs{>9^QAt={B{ZPt#5c($`ScNQg?vFrc0SRaf34}n(#28_=4&1`^ZUPm5#%Ch@Z_*GZr(#ef1gA<58Hxr7oIk|9yx#-~lb@$rbN#T7BQg>!%# z6*Uau5@S=65|2g2n8r=-sbd4t^S?IEk)Fn&fR=<3_fEwq{m^85{zk^bSS4Cw?RJcGO@Ix}Uw&HRPU>Q%u zl_=a_yT*@qs$zmycuf>KxOhzD#3?Mp1dx@bnCLIw<_LG7bSFws5)Pfw4#fDVcnI(A z`^!IO-nMR1;S@0}sh|s*6pxvkJ^me%SRa0XIwomqUR2b0f!BDG)aau~X;M@KlxQLt zQ}M>9csYr8UM8i&nk>53uo0Z_69zp3`Vb;YHh~)(d=z~5KLWd0KoUw5@R3>>CSn;R zhAtI>cm>@kL8K{-vF7#i?9(Vs>vSK=5@+iXN;5hWv0G4;Rv^n%0750^8g)jXngAee zgB~p~%_wcx?Ga}M$La~TGOk0nl}vuO##-yT!&(>Ub7#OEY}3Hi6pQXCaiZAz?6+qr3N3*Sv^<_^ku?4~sr-d%akUEF2bqf@#EuLx!x@j`b?(OCYvd^M zlPCP7L29aDGmT5V4sito!iOGocTL8lVwaMP#YCm+LR>iq;Q)sbt9eL>c;Gl7^U-mE zKa|=I&Pf$Z!Q+4&5Am{kC}1t`01hfv=Na_D;g5GNclOU91slQx!lhv0tl{d!1Hx$# zBWu_i4dVD3K8Zn$uF=pc*tivJcYcS#hT^g;hOm!P4Ym{!1SzB$bUY!(44VQHk`e}^ zCS*x7C>iD`DW(}VJ^|~3zsjI-G%=i(w^R+M>DI8nGHl?lB~dkq34_MY)u1#!Y|sk$ zCxd}=f&{6ABp8$m6{D%(u?)r(sX?6+r`0OhytJ{_7zvHdRhF(uy3*~oT zjV$*5GJdATp7IT$ugS;g>B8bBiRV-%h!-q zFSEJ6WnarJU;DDJeX)Mk*JVu)F8g-h@^vixIu=iT>FfSx9|-7M3gor^406|JrF_E@ z+qOivefun)!-9OEV&VVh@Du$$>JwWPuIqa{q4|T4>2I=!uEs#E z)-(lC0YyrY!ve*vP6>ogT}AJZmfb_lARY=y3ZzbNf`nLc6$zAXgIVwremWI6j1v)# z=O&X;KGvy-5KwW}B=h5}o$`?qLb-E|TV4dzsQCt@X0h0=gn%}NqTU4IF z)swi|gR3^E42NY5295DlY-}YpF6yt-WEljO%2Tj*2tIWPD$rhU&85MaBbnNQw{bo_ zo6e2qhZaMNrMhB`Gd0ubG3OUAIhJ~MOWC4nZ80*LuM?i=Jx0IEU_(1 zbc^W{LO`)xu-%xV=fDXpph_s$N-h;#F?J7Iisgs};#?mbulCW<0)cfQ2AO#pY30yf zNdO)evaMWPeW?=M;Mx$r%njVI58hI4(w15fsDi6ur(u@=0UJxkED@j8tF!`PNdfra zfMAx&sm=g)nn;srN~hG8%1#6ZU`o;j%t!MmCoTjIb~XXYt|*&^x6Ci-$YU1IN-H>S zI;~xqM#Q9T+IDMQry^J{w-ig#7G57Zdki5H+n#nn@?nN|GwosVJ*Hi{Q?QvmR(JNH zd3T5mqY!x(bSdrD-8!3sp5RVFJi1KIxoMR4z`QNevV}1Wb&u}STCI6Ac-wE3BqDf( zs+-;$rGyaz_%Mxt%5Dp~(h5Fn?~nl4BG}lr6rp+(gn!F2427Ca5IA~lDMGDKceB27 zbHJ%{3kVE_24UOH#tl$Rr0cs-mds(lbY$P7)~6wn(Hbp?T}au#QL6>}|3jNkLn=PE z?*b|&Od&|2LS))~0r{IwDA*8E?u{?k)HYF3;!02P)f$7>@qq;XD_YCM5c zDtKoVpBV6v#sKivHB*z+GbMa@iQxw_JOuIER}s%ACCI=6@P?KW01OmlnX3T#$u(^K zYdCQMR`v-gtV$`dlE{Ry)Wpv|>wQ23lo||08I0*-4O^5~&WVcQDz+FeRdo_xNL;%r z!qZq#{RZ6F>@vJs1??p?>8NcAKQm{wa5a&4agb5ikLAV5is33&&@uU?S1`)4|dG--DbU6`i-7j?BmPq9>;7e$n;FVX=l1-at;Qs( z+81}NI=VJMuG2JA_qC&K-G#h0^YW~me>NkpRPDWV6ryv@-TKFJ1Md!B8NPaArGD={ zWMe|atTRJpP8K}X*xMDOM|Z-`}e>6$i3|zBAGf zsbW|4iO+VFMZe$f9b|2PWS<{&P=B%$P#cb55Z`Su=yxjp0I0l(D|qxH!;aqzVEU$c zn2K*|tf>YV5C6^*44UsLGm9}ZCU_r3;TJMlJf!eI1m}us4^-\\t — producer registration + M \\t\\t — stat metadata + S \\t\\t\\t — stat sample +""" + +import sys +import collections +from pathlib import Path + +def parse_stats(path): + """Parse a plexdb .stats file into structured data.""" + producers = {} # producer_id -> name + stat_meta = {} # (producer_id, stat_id) -> name + # series key = (producer_id, stat_id) + series = collections.defaultdict(lambda: {"ts": [], "values": []}) + + with open(path) as f: + for line in f: + line = line.rstrip("\n") + if not line: + continue + tag = line[0] + rest = line[2:] # skip "X " + parts = rest.split("\t") + + if tag == "P" and len(parts) >= 2: + pid = int(parts[0]) + producers[pid] = parts[1] + + elif tag == "M" and len(parts) >= 3: + pid = int(parts[0]) + sid = int(parts[1]) + stat_meta[(pid, sid)] = parts[2] + + elif tag == "S" and len(parts) >= 4: + pid = int(parts[0]) + sid = int(parts[1]) + ts_ns = int(parts[2]) + value = int(parts[3]) + key = (pid, sid) + series[key]["ts"].append(ts_ns) + series[key]["values"].append(value) + + return producers, stat_meta, series + + +def label_for(producers, stat_meta, key): + """Build a human-readable label for a series key.""" + pid, sid = key + producer = producers.get(pid, f"producer:{pid}") + stat = stat_meta.get(key, f"stat:{sid}") + return f"{producer} / {stat}" + + +def main(): + path = sys.argv[1] if len(sys.argv) > 1 else "plexdb.stats" + if not Path(path).exists(): + print(f"error: file not found: {path}", file=sys.stderr) + print(__doc__, file=sys.stderr) + sys.exit(1) + + producers, stat_meta, series = parse_stats(path) + + if not series: + print("No stat samples found in", path) + sys.exit(0) + + try: + import matplotlib.pyplot as plt + except ImportError: + print("error: matplotlib is required. pip install matplotlib", file=sys.stderr) + sys.exit(1) + + fig, ax = plt.subplots(figsize=(12, 6)) + + for key, data in sorted(series.items()): + ts = data["ts"] + vals = data["values"] + # convert nanoseconds to seconds relative to first sample + t0 = ts[0] + t_sec = [(t - t0) / 1e9 for t in ts] + ax.plot(t_sec, vals, label=label_for(producers, stat_meta, key), marker=".", markersize=3) + + ax.set_xlabel("Time (seconds)") + ax.set_ylabel("Value") + ax.set_title("plexdb stats") + ax.legend(loc="best", fontsize="small") + ax.grid(True, alpha=0.3) + fig.tight_layout() + plt.show() + + +if __name__ == "__main__": + main() diff --git a/objstore/CMakeLists.txt b/objstore/CMakeLists.txt index a4a7466..6e18686 100644 --- a/objstore/CMakeLists.txt +++ b/objstore/CMakeLists.txt @@ -133,6 +133,19 @@ if(PLEXDB_LOG_ENABLED) PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}/../plexdb/log ) + + add_library(objstore_log_stat SHARED) + target_compile_features(objstore_log_stat PRIVATE cxx_std_20) + + target_sources(objstore_log_stat + PRIVATE + plugins/log_stat/log_stat_plugin.cpp + ) + + target_include_directories(objstore_log_stat + PRIVATE + ${CMAKE_CURRENT_SOURCE_DIR}/../plexdb/log + ) endif() # ============================================================================= diff --git a/objstore/plugins/log_file/log_file_plugin.cpp b/objstore/plugins/log_file/log_file_plugin.cpp index 16cd3db..ef1c0c3 100644 --- a/objstore/plugins/log_file/log_file_plugin.cpp +++ b/objstore/plugins/log_file/log_file_plugin.cpp @@ -12,6 +12,7 @@ #include #include #include +#include #include #include #include @@ -32,11 +33,12 @@ constexpr std::string DEFAULT_PLEXDB_LOG_FILE = "plexdb.log"; constexpr size_t DEFAULT_PLEXDB_LOG_BATCH = 1; struct State { - std::unordered_map producers; - std::vector buffer; - std::FILE* file = nullptr; - std::mutex mtx; - size_t batch = DEFAULT_PLEXDB_LOG_BATCH; + std::unordered_map producers; + std::map, std::string> stat_names; + std::vector buffer; + std::FILE* file = nullptr; + std::mutex mtx; + size_t batch = DEFAULT_PLEXDB_LOG_BATCH; State() { const char* path_cstr = std::getenv("PLEXDB_LOG_FILE"); @@ -94,13 +96,25 @@ struct State { line += '[' + it->second + "] "; } line += '[' + current_local_datetime() + "] "; - line += "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); + + auto sit = stat_names.find({producer_id, stat_id}); + if (sit != stat_names.end()) { + line += "[STAT:" + sit->second + "] " + std::to_string(value); + } else { + line += "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); + } + buffer.push_back(std::move(line)); if (buffer.size() >= batch) { flush_locked(); } } + void on_stat_meta(uint32_t producer_id, uint32_t stat_id, const char* name) { + std::lock_guard guard(mtx); + stat_names[{producer_id, stat_id}] = name; + } + void flush() { std::lock_guard guard(mtx); flush_locked(); @@ -144,6 +158,12 @@ void on_event(const PlexdbLogEvent* event, void* ctx) { event->stat.stat_id, event->stat.value); }break; + case PLEXDB_LOG_STAT_META:{ + state->on_stat_meta( + event->stat_meta.producer_id, + event->stat_meta.stat_id, + event->stat_meta.name); + }break; } } diff --git a/objstore/plugins/log_stat/log_stat_plugin.cpp b/objstore/plugins/log_stat/log_stat_plugin.cpp new file mode 100644 index 0000000..6cbb53c --- /dev/null +++ b/objstore/plugins/log_stat/log_stat_plugin.cpp @@ -0,0 +1,105 @@ +// Stat-logging plugin: writes structured stat events to a line-oriented text file. +// Designed for consumption by extra/plot_stats.py. +// +// Output format (one line per event, tab-separated): +// P \t — producer registration +// M \t\t — stat metadata +// S \t\t\t — stat sample +// +// Configuration (environment variables): +// PLEXDB_STAT_FILE – destination path (default: plexdb.stats) + +#include "log_abi.h" + +#include +#include +#include +#include +#include + +namespace { + +struct State { + std::FILE* file = nullptr; + std::mutex mtx; + + State() { + const char* path_cstr = std::getenv("PLEXDB_STAT_FILE"); + std::string path = path_cstr ? std::string(path_cstr) : "plexdb.stats"; + file = std::fopen(path.c_str(), "w"); + } + + ~State() { + if (file) std::fclose(file); + } + + void on_producer_registered(uint32_t id, const char* name) { + std::lock_guard guard(mtx); + if (!file) return; + std::fprintf(file, "P %u\t%s\n", id, name); + std::fflush(file); + } + + void on_stat_meta(uint32_t producer_id, uint32_t stat_id, const char* name) { + std::lock_guard guard(mtx); + if (!file) return; + std::fprintf(file, "M %u\t%u\t%s\n", producer_id, stat_id, name); + std::fflush(file); + } + + void on_stat(uint32_t producer_id, uint32_t stat_id, int64_t value) { + using namespace std::chrono; + auto ns = duration_cast(steady_clock::now().time_since_epoch()).count(); + + std::lock_guard guard(mtx); + if (!file) return; + std::fprintf(file, "S %u\t%u\t%lld\t%lld\n", + producer_id, stat_id, + static_cast(ns), + static_cast(value)); + std::fflush(file); + } +}; + +State* g_state = nullptr; + +void on_event(const PlexdbLogEvent* event, void* ctx) { + auto* state = static_cast(ctx); + switch (event->type) { + case PLEXDB_LOG_PRODUCER_REGISTERED: + state->on_producer_registered( + event->producer_registered.producer_id, + event->producer_registered.name); + break; + case PLEXDB_LOG_STAT_META: + state->on_stat_meta( + event->stat_meta.producer_id, + event->stat_meta.stat_id, + event->stat_meta.name); + break; + case PLEXDB_LOG_STAT: + state->on_stat( + event->stat.producer_id, + event->stat.stat_id, + event->stat.value); + break; + default: + break; + } +} + +} // namespace + +__attribute__((constructor)) +static void init() { + g_state = new State(); + plexdb_log_register_consumer(on_event, g_state); +} + +__attribute__((destructor)) +static void fini() { + if (!g_state) return; + plexdb_log_unregister_consumer(on_event, g_state); + delete g_state; + g_state = nullptr; +} diff --git a/objstore/test/log_consumer.test.cpp b/objstore/test/log_consumer.test.cpp index 1940b56..bf813c4 100644 --- a/objstore/test/log_consumer.test.cpp +++ b/objstore/test/log_consumer.test.cpp @@ -4,6 +4,7 @@ #include #include "log_abi.h" +#include #include #include #include @@ -11,9 +12,10 @@ namespace { struct LogBuffer { - std::vector entries; - std::mutex mtx; - bool active = false; + std::vector entries; + std::map stat_names; + std::mutex mtx; + bool active = false; void clear() { std::lock_guard g(mtx); @@ -34,10 +36,21 @@ struct LogBuffer { void push_stat(uint32_t stat_id, int64_t value) { std::lock_guard g(mtx); if (!active) return; - std::string entry = "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); + auto it = stat_names.find(stat_id); + std::string entry; + if (it != stat_names.end()) { + entry = "[STAT:" + it->second + "] " + std::to_string(value); + } else { + entry = "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); + } entries.push_back(std::move(entry)); UNSCOPED_INFO(entries.back()); } + + void register_stat_name(uint32_t stat_id, const char* name) { + std::lock_guard g(mtx); + stat_names[stat_id] = name; + } }; LogBuffer g_log_buffer; @@ -66,6 +79,11 @@ void on_log_event(const PlexdbLogEvent* event, void* /*ctx*/) { event->stat.stat_id, event->stat.value); break; + case PLEXDB_LOG_STAT_META: + g_log_buffer.register_stat_name( + event->stat_meta.stat_id, + event->stat_meta.name); + break; default: break; } diff --git a/plexdb/base/types.cppm b/plexdb/base/types.cppm index 2e0288d..893e86f 100644 --- a/plexdb/base/types.cppm +++ b/plexdb/base/types.cppm @@ -191,7 +191,8 @@ export namespace plexdb { using AssertHandler = void(*)(const char* msg, const char* file_name, const char* function_name, unsigned line_number); inline AssertHandler g_assert_handler = nullptr; - constexpr inline void assert_true_always(bool expr, const char* msg, std::source_location loc = std::source_location::current()) noexcept { + // @note not noexcept: the custom assert handler (e.g. Catch2 FAIL) may throw + constexpr inline void assert_true_always(bool expr, const char* msg, std::source_location loc = std::source_location::current()) { if (PLEXDB_IS_CONSTEVAL()) { PLEXDB_CONSTEVAL_TRAP(expr); } else { @@ -204,7 +205,7 @@ export namespace plexdb { } } } - constexpr inline void assert_true(bool expr, const char* msg, std::source_location loc = std::source_location::current()) noexcept { + constexpr inline void assert_true(bool expr, const char* msg, std::source_location loc = std::source_location::current()) { if constexpr (!k_assert_enabled) { if (!PLEXDB_IS_CONSTEVAL()) { return; @@ -213,11 +214,11 @@ export namespace plexdb { assert_true_always(expr, msg, loc); } - constexpr inline void assert_true_not_implemented(bool expr, const char* msg = not_implemented_msg, std::source_location loc = std::source_location::current()) noexcept { + constexpr inline void assert_true_not_implemented(bool expr, const char* msg = not_implemented_msg, std::source_location loc = std::source_location::current()) { assert_true_always(expr, msg, loc); } - constexpr inline void assert_not_implemented(const char* msg = not_implemented_msg, std::source_location loc = std::source_location::current()) noexcept { + constexpr inline void assert_not_implemented(const char* msg = not_implemented_msg, std::source_location loc = std::source_location::current()) { assert_true_not_implemented(false, msg, loc); } void set_assert_handler(AssertHandler h) noexcept; diff --git a/plexdb/log/log.cppm b/plexdb/log/log.cppm index be57c52..bf49398 100644 --- a/plexdb/log/log.cppm +++ b/plexdb/log/log.cppm @@ -84,6 +84,15 @@ export namespace plexdb::log { // zero-overhead structured numeric events for realtime metrics. // no string formatting overhead — consumers read the value directly. // ======================================================================== + inline void fire_stat_meta(uint32_t producer_id, uint32_t stat_id, const char* name) { + if constexpr (enabled) { + PlexdbLogEvent e{}; + e.type = PLEXDB_LOG_STAT_META; + e.stat_meta = {producer_id, stat_id, name}; + dispatch(e); + } + } + inline void fire_stat(uint32_t producer_id, uint32_t stat_id, int64_t value) { if constexpr (enabled) { PlexdbLogEvent e{}; diff --git a/plexdb/log/log.test.cpp b/plexdb/log/log.test.cpp index 4190c23..c4ae63b 100644 --- a/plexdb/log/log.test.cpp +++ b/plexdb/log/log.test.cpp @@ -1,6 +1,8 @@ #include #include "log_abi.h" +#include + import plexdb.log; using namespace plexdb::log; @@ -17,9 +19,13 @@ namespace { struct TestConsumer { unsigned message_count = 0; unsigned stat_count = 0; + unsigned meta_count = 0; uint32_t last_level = 0; int64_t last_stat_val = 0; uint32_t last_stat_id = 0; + uint32_t last_meta_producer = 0; + uint32_t last_meta_stat_id = 0; + const char* last_meta_name = nullptr; }; void test_on_event(const PlexdbLogEvent* event, void* ctx) { @@ -34,6 +40,12 @@ namespace { c->last_stat_id = event->stat.stat_id; c->last_stat_val = event->stat.value; break; + case PLEXDB_LOG_STAT_META: + c->meta_count++; + c->last_meta_producer = event->stat_meta.producer_id; + c->last_meta_stat_id = event->stat_meta.stat_id; + c->last_meta_name = event->stat_meta.name; + break; default: break; } @@ -93,3 +105,27 @@ TEST_CASE("fire_stat delivers structured metrics", "[plexdb.log]") { plexdb_log_unregister_consumer(test_on_event, &tc); } + +TEST_CASE("fire_stat_meta delivers metadata", "[plexdb.log]") { + if constexpr (!enabled) { + SKIP("logging disabled"); + } + + TestConsumer tc{}; + plexdb_log_register_consumer(test_on_event, &tc); + + Producer p{"test_meta"}; + + fire_stat_meta(p.id, 1, "requests_per_sec"); + CHECK(tc.meta_count == 1); + CHECK(tc.last_meta_producer == p.id); + CHECK(tc.last_meta_stat_id == 1); + CHECK(std::string(tc.last_meta_name) == "requests_per_sec"); + + fire_stat_meta(p.id, 2, "latency_ns"); + CHECK(tc.meta_count == 2); + CHECK(tc.last_meta_stat_id == 2); + CHECK(std::string(tc.last_meta_name) == "latency_ns"); + + plexdb_log_unregister_consumer(test_on_event, &tc); +} diff --git a/plexdb/log/log_abi.h b/plexdb/log/log_abi.h index 17b5729..e259918 100644 --- a/plexdb/log/log_abi.h +++ b/plexdb/log/log_abi.h @@ -22,6 +22,7 @@ typedef enum PlexdbLogEventType : uint32_t { PLEXDB_LOG_PRODUCER_REGISTERED = 1, // producer announces itself PLEXDB_LOG_MESSAGE = 2, // generic string message PLEXDB_LOG_STAT = 3, // structured numeric stat + PLEXDB_LOG_STAT_META = 4, // stat metadata (name for producer+stat_id pair) } PlexdbLogEventType; typedef struct { @@ -42,6 +43,12 @@ typedef struct { int64_t value; } PlexdbLogStat; +typedef struct { + uint32_t producer_id; + uint32_t stat_id; + const char* name; +} PlexdbLogStatMeta; + // @note fat struct with a type tag and union payload typedef struct { uint32_t type; // PlexdbLogEventType @@ -50,6 +57,7 @@ typedef struct { PlexdbLogProducerRegistered producer_registered; PlexdbLogMessage message; PlexdbLogStat stat; + PlexdbLogStatMeta stat_meta; }; } PlexdbLogEvent; diff --git a/plexdb/test/assert_helpers.test.cpp b/plexdb/test/assert_helpers.test.cpp index 852a43d..4f04b03 100644 --- a/plexdb/test/assert_helpers.test.cpp +++ b/plexdb/test/assert_helpers.test.cpp @@ -3,7 +3,7 @@ import plexdb.base; inline void catch2_assert_handler(const char* msg, const char* file_name, const char* function_name, unsigned line_number) { - FAIL_CHECK("Assert failed \"" << msg << "\" at " << function_name << " in " << file_name << ":" << line_number); + FAIL("Assert failed \"" << msg << "\" at " << function_name << " in " << file_name << ":" << line_number); } struct AssertHandlerInstaller { diff --git a/plexdb/test/log_consumer.test.cpp b/plexdb/test/log_consumer.test.cpp index 1940b56..bf813c4 100644 --- a/plexdb/test/log_consumer.test.cpp +++ b/plexdb/test/log_consumer.test.cpp @@ -4,6 +4,7 @@ #include #include "log_abi.h" +#include #include #include #include @@ -11,9 +12,10 @@ namespace { struct LogBuffer { - std::vector entries; - std::mutex mtx; - bool active = false; + std::vector entries; + std::map stat_names; + std::mutex mtx; + bool active = false; void clear() { std::lock_guard g(mtx); @@ -34,10 +36,21 @@ struct LogBuffer { void push_stat(uint32_t stat_id, int64_t value) { std::lock_guard g(mtx); if (!active) return; - std::string entry = "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); + auto it = stat_names.find(stat_id); + std::string entry; + if (it != stat_names.end()) { + entry = "[STAT:" + it->second + "] " + std::to_string(value); + } else { + entry = "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); + } entries.push_back(std::move(entry)); UNSCOPED_INFO(entries.back()); } + + void register_stat_name(uint32_t stat_id, const char* name) { + std::lock_guard g(mtx); + stat_names[stat_id] = name; + } }; LogBuffer g_log_buffer; @@ -66,6 +79,11 @@ void on_log_event(const PlexdbLogEvent* event, void* /*ctx*/) { event->stat.stat_id, event->stat.value); break; + case PLEXDB_LOG_STAT_META: + g_log_buffer.register_stat_name( + event->stat_meta.stat_id, + event->stat_meta.name); + break; default: break; } From 794543dd06c2ad56aae875586fe7214606282d1d Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 16 Mar 2026 09:32:59 +0000 Subject: [PATCH 05/10] Fix stat_names key to use (producer_id, stat_id) pair, remove __pycache__ Co-authored-by: patricklbell <46551885+patricklbell@users.noreply.github.com> --- .gitignore | 3 ++- extra/__pycache__/plot_stats.cpython-312.pyc | Bin 5236 -> 0 bytes objstore/test/log_consumer.test.cpp | 18 ++++++++++-------- plexdb/test/log_consumer.test.cpp | 18 ++++++++++-------- 4 files changed, 22 insertions(+), 17 deletions(-) delete mode 100644 extra/__pycache__/plot_stats.cpython-312.pyc diff --git a/.gitignore b/.gitignore index 842b4d9..ca3e1bf 100644 --- a/.gitignore +++ b/.gitignore @@ -7,4 +7,5 @@ _codeql_detected_source_root *.stats objstore.pid **/.venv -**/node_modules \ No newline at end of file +**/node_modules +**/__pycache__ \ No newline at end of file diff --git a/extra/__pycache__/plot_stats.cpython-312.pyc b/extra/__pycache__/plot_stats.cpython-312.pyc deleted file mode 100644 index 77ed8abbbd7bf46960b35a5d61db7a62537dbc81..0000000000000000000000000000000000000000 GIT binary patch literal 0 HcmV?d00001 literal 5236 zcmcH-TTC3+_0DTwv&$||1Bso%*oKW^iG}kbwi|4~U||;pyNao;?XWW}vz~o;W)_>( zY>TBtSrR1HNhH>_qima~!m>Y7sZ#P8DXrS7i3)+lo2etYt$+9rs{>9^QAt={B{ZPt#5c($`ScNQg?vFrc0SRaf34}n(#28_=4&1`^ZUPm5#%Ch@Z_*GZr(#ef1gA<58Hxr7oIk|9yx#-~lb@$rbN#T7BQg>!%# z6*Uau5@S=65|2g2n8r=-sbd4t^S?IEk)Fn&fR=<3_fEwq{m^85{zk^bSS4Cw?RJcGO@Ix}Uw&HRPU>Q%u zl_=a_yT*@qs$zmycuf>KxOhzD#3?Mp1dx@bnCLIw<_LG7bSFws5)Pfw4#fDVcnI(A z`^!IO-nMR1;S@0}sh|s*6pxvkJ^me%SRa0XIwomqUR2b0f!BDG)aau~X;M@KlxQLt zQ}M>9csYr8UM8i&nk>53uo0Z_69zp3`Vb;YHh~)(d=z~5KLWd0KoUw5@R3>>CSn;R zhAtI>cm>@kL8K{-vF7#i?9(Vs>vSK=5@+iXN;5hWv0G4;Rv^n%0750^8g)jXngAee zgB~p~%_wcx?Ga}M$La~TGOk0nl}vuO##-yT!&(>Ub7#OEY}3Hi6pQXCaiZAz?6+qr3N3*Sv^<_^ku?4~sr-d%akUEF2bqf@#EuLx!x@j`b?(OCYvd^M zlPCP7L29aDGmT5V4sito!iOGocTL8lVwaMP#YCm+LR>iq;Q)sbt9eL>c;Gl7^U-mE zKa|=I&Pf$Z!Q+4&5Am{kC}1t`01hfv=Na_D;g5GNclOU91slQx!lhv0tl{d!1Hx$# zBWu_i4dVD3K8Zn$uF=pc*tivJcYcS#hT^g;hOm!P4Ym{!1SzB$bUY!(44VQHk`e}^ zCS*x7C>iD`DW(}VJ^|~3zsjI-G%=i(w^R+M>DI8nGHl?lB~dkq34_MY)u1#!Y|sk$ zCxd}=f&{6ABp8$m6{D%(u?)r(sX?6+r`0OhytJ{_7zvHdRhF(uy3*~oT zjV$*5GJdATp7IT$ugS;g>B8bBiRV-%h!-q zFSEJ6WnarJU;DDJeX)Mk*JVu)F8g-h@^vixIu=iT>FfSx9|-7M3gor^406|JrF_E@ z+qOivefun)!-9OEV&VVh@Du$$>JwWPuIqa{q4|T4>2I=!uEs#E z)-(lC0YyrY!ve*vP6>ogT}AJZmfb_lARY=y3ZzbNf`nLc6$zAXgIVwremWI6j1v)# z=O&X;KGvy-5KwW}B=h5}o$`?qLb-E|TV4dzsQCt@X0h0=gn%}NqTU4IF z)swi|gR3^E42NY5295DlY-}YpF6yt-WEljO%2Tj*2tIWPD$rhU&85MaBbnNQw{bo_ zo6e2qhZaMNrMhB`Gd0ubG3OUAIhJ~MOWC4nZ80*LuM?i=Jx0IEU_(1 zbc^W{LO`)xu-%xV=fDXpph_s$N-h;#F?J7Iisgs};#?mbulCW<0)cfQ2AO#pY30yf zNdO)evaMWPeW?=M;Mx$r%njVI58hI4(w15fsDi6ur(u@=0UJxkED@j8tF!`PNdfra zfMAx&sm=g)nn;srN~hG8%1#6ZU`o;j%t!MmCoTjIb~XXYt|*&^x6Ci-$YU1IN-H>S zI;~xqM#Q9T+IDMQry^J{w-ig#7G57Zdki5H+n#nn@?nN|GwosVJ*Hi{Q?QvmR(JNH zd3T5mqY!x(bSdrD-8!3sp5RVFJi1KIxoMR4z`QNevV}1Wb&u}STCI6Ac-wE3BqDf( zs+-;$rGyaz_%Mxt%5Dp~(h5Fn?~nl4BG}lr6rp+(gn!F2427Ca5IA~lDMGDKceB27 zbHJ%{3kVE_24UOH#tl$Rr0cs-mds(lbY$P7)~6wn(Hbp?T}au#QL6>}|3jNkLn=PE z?*b|&Od&|2LS))~0r{IwDA*8E?u{?k)HYF3;!02P)f$7>@qq;XD_YCM5c zDtKoVpBV6v#sKivHB*z+GbMa@iQxw_JOuIER}s%ACCI=6@P?KW01OmlnX3T#$u(^K zYdCQMR`v-gtV$`dlE{Ry)Wpv|>wQ23lo||08I0*-4O^5~&WVcQDz+FeRdo_xNL;%r z!qZq#{RZ6F>@vJs1??p?>8NcAKQm{wa5a&4agb5ikLAV5is33&&@uU?S1`)4|dG--DbU6`i-7j?BmPq9>;7e$n;FVX=l1-at;Qs( z+81}NI=VJMuG2JA_qC&K-G#h0^YW~me>NkpRPDWV6ryv@-TKFJ1Md!B8NPaArGD={ zWMe|atTRJpP8K}X*xMDOM|Z-`}e>6$i3|zBAGf zsbW|4iO+VFMZe$f9b|2PWS<{&P=B%$P#cb55Z`Su=yxjp0I0l(D|qxH!;aqzVEU$c zn2K*|tf>YV5C6^*44UsLGm9}ZCU_r3;TJMlJf!eI1m}us4^- entries; - std::map stat_names; - std::mutex mtx; - bool active = false; + std::vector entries; + std::map, std::string> stat_names; + std::mutex mtx; + bool active = false; void clear() { std::lock_guard g(mtx); @@ -33,10 +33,10 @@ struct LogBuffer { UNSCOPED_INFO(entries.back()); } - void push_stat(uint32_t stat_id, int64_t value) { + void push_stat(uint32_t producer_id, uint32_t stat_id, int64_t value) { std::lock_guard g(mtx); if (!active) return; - auto it = stat_names.find(stat_id); + auto it = stat_names.find({producer_id, stat_id}); std::string entry; if (it != stat_names.end()) { entry = "[STAT:" + it->second + "] " + std::to_string(value); @@ -47,9 +47,9 @@ struct LogBuffer { UNSCOPED_INFO(entries.back()); } - void register_stat_name(uint32_t stat_id, const char* name) { + void register_stat_name(uint32_t producer_id, uint32_t stat_id, const char* name) { std::lock_guard g(mtx); - stat_names[stat_id] = name; + stat_names[{producer_id, stat_id}] = name; } }; @@ -76,11 +76,13 @@ void on_log_event(const PlexdbLogEvent* event, void* /*ctx*/) { break; case PLEXDB_LOG_STAT: g_log_buffer.push_stat( + event->stat.producer_id, event->stat.stat_id, event->stat.value); break; case PLEXDB_LOG_STAT_META: g_log_buffer.register_stat_name( + event->stat_meta.producer_id, event->stat_meta.stat_id, event->stat_meta.name); break; diff --git a/plexdb/test/log_consumer.test.cpp b/plexdb/test/log_consumer.test.cpp index bf813c4..4ae3313 100644 --- a/plexdb/test/log_consumer.test.cpp +++ b/plexdb/test/log_consumer.test.cpp @@ -12,10 +12,10 @@ namespace { struct LogBuffer { - std::vector entries; - std::map stat_names; - std::mutex mtx; - bool active = false; + std::vector entries; + std::map, std::string> stat_names; + std::mutex mtx; + bool active = false; void clear() { std::lock_guard g(mtx); @@ -33,10 +33,10 @@ struct LogBuffer { UNSCOPED_INFO(entries.back()); } - void push_stat(uint32_t stat_id, int64_t value) { + void push_stat(uint32_t producer_id, uint32_t stat_id, int64_t value) { std::lock_guard g(mtx); if (!active) return; - auto it = stat_names.find(stat_id); + auto it = stat_names.find({producer_id, stat_id}); std::string entry; if (it != stat_names.end()) { entry = "[STAT:" + it->second + "] " + std::to_string(value); @@ -47,9 +47,9 @@ struct LogBuffer { UNSCOPED_INFO(entries.back()); } - void register_stat_name(uint32_t stat_id, const char* name) { + void register_stat_name(uint32_t producer_id, uint32_t stat_id, const char* name) { std::lock_guard g(mtx); - stat_names[stat_id] = name; + stat_names[{producer_id, stat_id}] = name; } }; @@ -76,11 +76,13 @@ void on_log_event(const PlexdbLogEvent* event, void* /*ctx*/) { break; case PLEXDB_LOG_STAT: g_log_buffer.push_stat( + event->stat.producer_id, event->stat.stat_id, event->stat.value); break; case PLEXDB_LOG_STAT_META: g_log_buffer.register_stat_name( + event->stat_meta.producer_id, event->stat_meta.stat_id, event->stat_meta.name); break; From 98d2effd518da6b8371afa07ba448a3769bc7790 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 19 Mar 2026 10:00:15 +0000 Subject: [PATCH 06/10] Fix test core dump, add producer metadata, refactor plugins to functions, add real-time dashboard plugin - Fix SKIP() crash: replace with compile-time return (SKIP requires exceptions) - Fix FAIL() crash: use FAIL_CHECK + longjmp recovery + Catch2 listener - Add PLEXDB_TEST_SCOPE macro for graceful test recovery from assertions - Enable PLEXDB_LOG_ENABLED and PLEXDB_DEBUG in CI test.yml - Rename log_consumer.test.cpp to log_consumer_helper.test.cpp - Add PLEXDB_LOG_PRODUCER_META event type to log ABI - Add fire_producer_meta() to C++ log module - Refactor log_stat, log_file plugins to use functions instead of OOP - Create real-time terminal dashboard plugin (log_dashboard) - Update plot_stats.py with --live mode and producer metadata support - Add test for fire_producer_meta Co-authored-by: patricklbell <46551885+patricklbell@users.noreply.github.com> --- .github/workflows/test.yml | 2 +- extra/plot_stats.py | 108 +++++++- objstore/CMakeLists.txt | 13 + .../log_dashboard/log_dashboard_plugin.cpp | 237 +++++++++++++++++ objstore/plugins/log_file/log_file_plugin.cpp | 240 ++++++++++-------- objstore/plugins/log_stat/log_stat_plugin.cpp | 105 ++++---- objstore/test/assert_helpers.test.cpp | 1 + objstore/test/log_consumer.test.cpp | 116 --------- objstore/test/log_consumer_helper.test.cpp | 167 ++++++++++++ plexdb/log/log.cppm | 9 + plexdb/log/log.test.cpp | 44 +++- plexdb/log/log_abi.h | 8 + plexdb/test/assert_helpers.test.cpp | 66 ++++- plexdb/test/log_consumer.test.cpp | 116 --------- plexdb/test/log_consumer_helper.test.cpp | 167 ++++++++++++ 15 files changed, 988 insertions(+), 411 deletions(-) create mode 100644 objstore/plugins/log_dashboard/log_dashboard_plugin.cpp delete mode 100644 objstore/test/log_consumer.test.cpp create mode 100644 objstore/test/log_consumer_helper.test.cpp delete mode 100644 plexdb/test/log_consumer.test.cpp create mode 100644 plexdb/test/log_consumer_helper.test.cpp diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 6a28824..262e028 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -19,7 +19,7 @@ jobs: sudo apt-get install -y ninja-build liburing-dev clang-19 clang-tools-19 - name: Configure - run: cmake -B build -G Ninja -DBUILD_TESTS=ON -DCMAKE_BUILD_TYPE=Debug -DCMAKE_CXX_COMPILER=clang++-19 -DCMAKE_C_COMPILER=clang-19 + run: cmake -B build -G Ninja -DBUILD_TESTS=ON -DPLEXDB_LOG_ENABLED=ON -DPLEXDB_DEBUG=ON -DCMAKE_BUILD_TYPE=Debug -DCMAKE_CXX_COMPILER=clang++-19 -DCMAKE_C_COMPILER=clang-19 - name: Build run: ninja -C build diff --git a/extra/plot_stats.py b/extra/plot_stats.py index 1823e86..90a4475 100644 --- a/extra/plot_stats.py +++ b/extra/plot_stats.py @@ -2,7 +2,8 @@ """Plot stats from the plexdb log_stat plugin output. Usage: - python extra/plot_stats.py [plexdb.stats] + python extra/plot_stats.py [plexdb.stats] # static plot + python extra/plot_stats.py --live [plexdb.stats] # real-time terminal view The input file is produced by the objstore_log_stat plugin. Set the environment variable PLEXDB_STAT_FILE to control the output path @@ -12,19 +13,28 @@ ./build/objstore/objstore_server ... python extra/plot_stats.py my.stats +For the real-time terminal dashboard, prefer the native C++ dashboard plugin: + LD_PRELOAD=./build/objstore/libobjstore_log_dashboard.so \\ + ./build/objstore/objstore_server ... + File format (tab-separated, one event per line): P \\t — producer registration + D \\t\\t — producer metadata M \\t\\t — stat metadata S \\t\\t\\t — stat sample """ import sys +import os +import time import collections from pathlib import Path + def parse_stats(path): """Parse a plexdb .stats file into structured data.""" producers = {} # producer_id -> name + producer_meta = {} # (producer_id, key) -> value stat_meta = {} # (producer_id, stat_id) -> name # series key = (producer_id, stat_id) series = collections.defaultdict(lambda: {"ts": [], "values": []}) @@ -42,6 +52,10 @@ def parse_stats(path): pid = int(parts[0]) producers[pid] = parts[1] + elif tag == "D" and len(parts) >= 3: + pid = int(parts[0]) + producer_meta[(pid, parts[1])] = parts[2] + elif tag == "M" and len(parts) >= 3: pid = int(parts[0]) sid = int(parts[1]) @@ -56,7 +70,7 @@ def parse_stats(path): series[key]["ts"].append(ts_ns) series[key]["values"].append(value) - return producers, stat_meta, series + return producers, producer_meta, stat_meta, series def label_for(producers, stat_meta, key): @@ -67,14 +81,73 @@ def label_for(producers, stat_meta, key): return f"{producer} / {stat}" -def main(): - path = sys.argv[1] if len(sys.argv) > 1 else "plexdb.stats" - if not Path(path).exists(): - print(f"error: file not found: {path}", file=sys.stderr) - print(__doc__, file=sys.stderr) - sys.exit(1) +def render_live(path): + """Tail the stats file and render a real-time terminal dashboard.""" + last_pos = 0 + producers = {} + producer_meta = {} + stat_meta = {} + stat_values = {} + + while True: + try: + with open(path) as f: + f.seek(last_pos) + new_lines = f.readlines() + last_pos = f.tell() + except FileNotFoundError: + time.sleep(0.5) + continue + + for raw in new_lines: + line = raw.rstrip("\n") + if not line: + continue + tag = line[0] + rest = line[2:] + parts = rest.split("\t") - producers, stat_meta, series = parse_stats(path) + if tag == "P" and len(parts) >= 2: + producers[int(parts[0])] = parts[1] + elif tag == "D" and len(parts) >= 3: + producer_meta[(int(parts[0]), parts[1])] = parts[2] + elif tag == "M" and len(parts) >= 3: + stat_meta[(int(parts[0]), int(parts[1]))] = parts[2] + elif tag == "S" and len(parts) >= 4: + stat_values[(int(parts[0]), int(parts[1]))] = int(parts[3]) + + # render + sys.stdout.write("\033[H\033[2J") + sys.stdout.write("\033[1;36m=== plexdb stats (live) ===\033[0m\n\n") + + by_producer = collections.defaultdict(list) + for key in sorted(stat_values): + by_producer[key[0]].append(key) + + for pid, keys in by_producer.items(): + pname = producers.get(pid, f"producer:{pid}") + meta_str = " ".join( + f"\033[2m{k}={v}\033[0m" + for (mid, k), v in sorted(producer_meta.items()) + if mid == pid + ) + sys.stdout.write(f" \033[1;33m{pname}\033[0m (id={pid}) {meta_str}\n") + for key in keys: + sname = stat_meta.get(key, f"stat:{key[1]}") + val = stat_values[key] + sys.stdout.write(f" {sname:<30s} \033[1;32m{val}\033[0m\n") + sys.stdout.write("\n") + + if not stat_values: + sys.stdout.write(" \033[2m(waiting for stats...)\033[0m\n") + + sys.stdout.flush() + time.sleep(0.5) + + +def plot_static(path): + """Static matplotlib plot.""" + producers, producer_meta, stat_meta, series = parse_stats(path) if not series: print("No stat samples found in", path) @@ -91,7 +164,6 @@ def main(): for key, data in sorted(series.items()): ts = data["ts"] vals = data["values"] - # convert nanoseconds to seconds relative to first sample t0 = ts[0] t_sec = [(t - t0) / 1e9 for t in ts] ax.plot(t_sec, vals, label=label_for(producers, stat_meta, key), marker=".", markersize=3) @@ -105,5 +177,21 @@ def main(): plt.show() +def main(): + live = "--live" in sys.argv + args = [a for a in sys.argv[1:] if a != "--live"] + path = args[0] if args else "plexdb.stats" + + if not live and not Path(path).exists(): + print(f"error: file not found: {path}", file=sys.stderr) + print(__doc__, file=sys.stderr) + sys.exit(1) + + if live: + render_live(path) + else: + plot_static(path) + + if __name__ == "__main__": main() diff --git a/objstore/CMakeLists.txt b/objstore/CMakeLists.txt index 6e18686..917ba3f 100644 --- a/objstore/CMakeLists.txt +++ b/objstore/CMakeLists.txt @@ -146,6 +146,19 @@ if(PLEXDB_LOG_ENABLED) PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}/../plexdb/log ) + + add_library(objstore_log_dashboard SHARED) + target_compile_features(objstore_log_dashboard PRIVATE cxx_std_20) + + target_sources(objstore_log_dashboard + PRIVATE + plugins/log_dashboard/log_dashboard_plugin.cpp + ) + + target_include_directories(objstore_log_dashboard + PRIVATE + ${CMAKE_CURRENT_SOURCE_DIR}/../plexdb/log + ) endif() # ============================================================================= diff --git a/objstore/plugins/log_dashboard/log_dashboard_plugin.cpp b/objstore/plugins/log_dashboard/log_dashboard_plugin.cpp new file mode 100644 index 0000000..304be72 --- /dev/null +++ b/objstore/plugins/log_dashboard/log_dashboard_plugin.cpp @@ -0,0 +1,237 @@ +// Real-time terminal dashboard plugin: renders live database stats using ANSI +// escape codes. Loaded via LD_PRELOAD alongside the server binary. +// +// Usage: +// LD_PRELOAD=./build/objstore/libobjstore_log_dashboard.so \ +// ./build/objstore/objstore_server ... +// +// Configuration (environment variables): +// PLEXDB_DASHBOARD_INTERVAL_MS – minimum refresh interval (default: 500) +// PLEXDB_DASHBOARD_FD – file descriptor to write to (default: 2, stderr) + +#include "log_abi.h" + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +namespace { + +// ============================================================================ +// state +// ============================================================================ +struct DashboardState { + std::unordered_map producer_names; + std::map, std::string> producer_meta; + std::map, std::string> stat_names; + std::map, int64_t> stat_values; + std::vector> recent_logs; + std::mutex mtx; + std::chrono::steady_clock::time_point last_render; + std::chrono::milliseconds interval; + std::FILE* out; + unsigned max_recent_logs; +}; + +DashboardState* g_state = nullptr; + +// ============================================================================ +// rendering +// ============================================================================ +void render_dashboard(DashboardState* s) { + auto now = std::chrono::steady_clock::now(); + if (now - s->last_render < s->interval) return; + s->last_render = now; + + std::FILE* f = s->out; + + // ANSI: move cursor home + clear screen + std::fprintf(f, "\033[H\033[2J"); + + std::fprintf(f, "\033[1;36m╔══════════════════════════════════════════════════════════════╗\033[0m\n"); + std::fprintf(f, "\033[1;36m║\033[0m \033[1;37mplexdb real-time dashboard\033[0m \033[1;36m║\033[0m\n"); + std::fprintf(f, "\033[1;36m╠══════════════════════════════════════════════════════════════╣\033[0m\n"); + + // group stats by producer + std::map>> by_producer; + for (const auto& [key, val] : s->stat_values) { + by_producer[key.first].push_back(key); + } + + for (const auto& [pid, keys] : by_producer) { + auto name_it = s->producer_names.find(pid); + const char* pname = (name_it != s->producer_names.end()) ? name_it->second.c_str() : "???"; + std::fprintf(f, "\033[1;36m║\033[0m \033[1;33m▸ %s\033[0m (id=%u)", pname, pid); + + // show producer metadata inline + for (const auto& [mk, mv] : s->producer_meta) { + if (mk.first == pid) { + std::fprintf(f, " \033[2m%s=%s\033[0m", mk.second.c_str(), mv.c_str()); + } + } + + // pad to box width + std::fprintf(f, "\n"); + + for (const auto& key : keys) { + auto sname_it = s->stat_names.find(key); + int64_t value = s->stat_values[key]; + if (sname_it != s->stat_names.end()) { + std::fprintf(f, "\033[1;36m║\033[0m \033[37m%-30s\033[0m \033[1;32m%lld\033[0m\n", + sname_it->second.c_str(), static_cast(value)); + } else { + std::fprintf(f, "\033[1;36m║\033[0m \033[37mstat:%u\033[0m \033[1;32m%lld\033[0m\n", + key.second, static_cast(value)); + } + } + } + + if (by_producer.empty()) { + std::fprintf(f, "\033[1;36m║\033[0m \033[2m(no stats yet)\033[0m\n"); + } + + // recent log messages + if (!s->recent_logs.empty()) { + std::fprintf(f, "\033[1;36m╠══════════════════════════════════════════════════════════════╣\033[0m\n"); + std::fprintf(f, "\033[1;36m║\033[0m \033[1;37mrecent log messages\033[0m\n"); + for (const auto& [level, text] : s->recent_logs) { + const char* color = "\033[37m"; + if (level == "ERROR") color = "\033[1;31m"; + else if (level == "WARN") color = "\033[1;33m"; + else if (level == "DEBUG") color = "\033[2m"; + else if (level == "TRACE") color = "\033[2m"; + std::fprintf(f, "\033[1;36m║\033[0m %s[%s]\033[0m %.50s\n", + color, level.c_str(), text.c_str()); + } + } + + std::fprintf(f, "\033[1;36m╚══════════════════════════════════════════════════════════════╝\033[0m\n"); + std::fflush(f); +} + +// ============================================================================ +// event handlers +// ============================================================================ +void handle_producer_registered(DashboardState* s, uint32_t id, const char* name) { + std::lock_guard guard(s->mtx); + s->producer_names[id] = name; + render_dashboard(s); +} + +void handle_producer_meta(DashboardState* s, uint32_t producer_id, const char* key, const char* value) { + std::lock_guard guard(s->mtx); + s->producer_meta[{producer_id, std::string(key)}] = value; + render_dashboard(s); +} + +void handle_message(DashboardState* s, uint32_t level, const char* text, size_t len) { + static constexpr const char* level_tags[] = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR"}; + constexpr size_t n_levels = sizeof(level_tags) / sizeof(level_tags[0]); + const char* tag = (level < n_levels) ? level_tags[level] : "???"; + + std::lock_guard guard(s->mtx); + s->recent_logs.push_back({tag, std::string(text, len)}); + if (s->recent_logs.size() > s->max_recent_logs) { + s->recent_logs.erase(s->recent_logs.begin()); + } + render_dashboard(s); +} + +void handle_stat(DashboardState* s, uint32_t producer_id, uint32_t stat_id, int64_t value) { + std::lock_guard guard(s->mtx); + s->stat_values[{producer_id, stat_id}] = value; + render_dashboard(s); +} + +void handle_stat_meta(DashboardState* s, uint32_t producer_id, uint32_t stat_id, const char* name) { + std::lock_guard guard(s->mtx); + s->stat_names[{producer_id, stat_id}] = name; + render_dashboard(s); +} + +// ============================================================================ +// consumer callback +// ============================================================================ +void on_event(const PlexdbLogEvent* event, void* ctx) { + auto* s = static_cast(ctx); + switch (event->type) { + case PLEXDB_LOG_PRODUCER_REGISTERED: + handle_producer_registered(s, + event->producer_registered.producer_id, + event->producer_registered.name); + break; + case PLEXDB_LOG_PRODUCER_META: + handle_producer_meta(s, + event->producer_meta.producer_id, + event->producer_meta.key, + event->producer_meta.value); + break; + case PLEXDB_LOG_MESSAGE: + handle_message(s, + event->message.level, + event->message.text, + event->message.text_len); + break; + case PLEXDB_LOG_STAT: + handle_stat(s, + event->stat.producer_id, + event->stat.stat_id, + event->stat.value); + break; + case PLEXDB_LOG_STAT_META: + handle_stat_meta(s, + event->stat_meta.producer_id, + event->stat_meta.stat_id, + event->stat_meta.name); + break; + default: + break; + } +} + +// ============================================================================ +// lifecycle +// ============================================================================ +DashboardState* dashboard_init() { + auto* s = new DashboardState{}; + + const char* interval_env = std::getenv("PLEXDB_DASHBOARD_INTERVAL_MS"); + unsigned ms = interval_env ? static_cast(std::atoi(interval_env)) : 500; + if (ms == 0) ms = 500; + s->interval = std::chrono::milliseconds(ms); + + const char* fd_env = std::getenv("PLEXDB_DASHBOARD_FD"); + int fd = fd_env ? std::atoi(fd_env) : 2; + s->out = (fd == 1) ? stdout : stderr; + + s->max_recent_logs = 8; + s->last_render = std::chrono::steady_clock::now() - s->interval; + return s; +} + +void dashboard_fini(DashboardState* s) { + if (!s) return; + delete s; +} + +} // namespace + +__attribute__((constructor)) +static void init() { + g_state = dashboard_init(); + plexdb_log_register_consumer(on_event, g_state); +} + +__attribute__((destructor)) +static void fini() { + if (!g_state) return; + plexdb_log_unregister_consumer(on_event, g_state); + dashboard_fini(g_state); + g_state = nullptr; +} diff --git a/objstore/plugins/log_file/log_file_plugin.cpp b/objstore/plugins/log_file/log_file_plugin.cpp index ef1c0c3..7027dd6 100644 --- a/objstore/plugins/log_file/log_file_plugin.cpp +++ b/objstore/plugins/log_file/log_file_plugin.cpp @@ -1,11 +1,9 @@ // Log-file plugin: writes structured plexdb log events to a text file. -// Handles PLEXDB_LOG_PRODUCER_REGISTERED (records producer names) and -// PLEXDB_LOG_MESSAGE (appends "[producer] text" lines). Uses STL since -// plugins are not subject to the no-STL rule. +// Handles all event types with human-readable formatting. // // Configuration (environment variables): // PLEXDB_LOG_FILE – destination path (default: plexdb.log) -// PLEXDB_LOG_BATCH – lines per flush (default: 64) +// PLEXDB_LOG_BATCH – lines per flush (default: 1) #include "log_abi.h" @@ -29,159 +27,181 @@ std::string current_local_datetime() { return std::format("{:%Y-%m-%d %H:%M:%S}", zt.get_local_time()); } -constexpr std::string DEFAULT_PLEXDB_LOG_FILE = "plexdb.log"; +constexpr const char* DEFAULT_PLEXDB_LOG_FILE = "plexdb.log"; constexpr size_t DEFAULT_PLEXDB_LOG_BATCH = 1; -struct State { +struct FilePluginState { std::unordered_map producers; std::map, std::string> stat_names; std::vector buffer; - std::FILE* file = nullptr; + std::FILE* file; std::mutex mtx; - size_t batch = DEFAULT_PLEXDB_LOG_BATCH; - - State() { - const char* path_cstr = std::getenv("PLEXDB_LOG_FILE"); - std::string path = (!path_cstr) ? DEFAULT_PLEXDB_LOG_FILE : std::string(path_cstr); + size_t batch; +}; - const char* batch_env = std::getenv("PLEXDB_LOG_BATCH"); - if (batch_env) { - size_t v = static_cast(std::atol(batch_env)); - if (v > 0) { - batch = v; - } - } +FilePluginState* g_state = nullptr; - file = std::fopen(path.c_str(), "a"); +// ============================================================================ +// buffer management +// ============================================================================ +void flush_buffer(FilePluginState* s) { + if (!s->file || s->buffer.empty()) return; + for (const auto& entry : s->buffer) { + std::fwrite(entry.data(), 1, entry.size(), s->file); + std::fputc('\n', s->file); } + std::fflush(s->file); + s->buffer.clear(); +} - ~State() { - flush(); - if (file) std::fclose(file); +void append_line(FilePluginState* s, std::string line) { + s->buffer.push_back(std::move(line)); + if (s->buffer.size() >= s->batch) { + flush_buffer(s); } +} - void on_producer_registered(uint32_t id, const char* name) { - std::lock_guard guard(mtx); - producers[id] = name; +std::string producer_prefix(FilePluginState* s, uint32_t producer_id) { + std::string prefix; + auto it = s->producers.find(producer_id); + if (it != s->producers.end()) { + prefix += '[' + it->second + "] "; } + prefix += '[' + current_local_datetime() + "] "; + return prefix; +} - void on_message(uint32_t producer_id, uint32_t level, const char* text, size_t len) { - static constexpr const char* level_tags[] = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR"}; - constexpr size_t n_levels = sizeof(level_tags) / sizeof(level_tags[0]); - const char* tag = (level < n_levels) ? level_tags[level] : "???"; - - std::lock_guard guard(mtx); - std::string line = ""; - auto it = producers.find(producer_id); - if (it != producers.end()) { - line += '[' + it->second + "] "; - } - line += '[' + current_local_datetime() + "] "; - line += '['; - line += tag; - line += "] "; - - line.append(text, len); - buffer.push_back(std::move(line)); - if (buffer.size() >= batch) { - flush_locked(); - } - } +// ============================================================================ +// event handlers +// ============================================================================ +void handle_producer_registered(FilePluginState* s, uint32_t id, const char* name) { + std::lock_guard guard(s->mtx); + s->producers[id] = name; +} - void on_stat(uint32_t producer_id, uint32_t stat_id, int64_t value) { - std::lock_guard guard(mtx); - std::string line = ""; - auto it = producers.find(producer_id); - if (it != producers.end()) { - line += '[' + it->second + "] "; - } - line += '[' + current_local_datetime() + "] "; - - auto sit = stat_names.find({producer_id, stat_id}); - if (sit != stat_names.end()) { - line += "[STAT:" + sit->second + "] " + std::to_string(value); - } else { - line += "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); - } - - buffer.push_back(std::move(line)); - if (buffer.size() >= batch) { - flush_locked(); - } - } +void handle_producer_meta(FilePluginState* s, uint32_t producer_id, const char* key, const char* value) { + std::lock_guard guard(s->mtx); + std::string line = producer_prefix(s, producer_id); + line += "[META] "; + line += key; + line += "="; + line += value; + append_line(s, std::move(line)); +} - void on_stat_meta(uint32_t producer_id, uint32_t stat_id, const char* name) { - std::lock_guard guard(mtx); - stat_names[{producer_id, stat_id}] = name; - } +void handle_message(FilePluginState* s, uint32_t producer_id, uint32_t level, + const char* text, size_t len) { + static constexpr const char* level_tags[] = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR"}; + constexpr size_t n_levels = sizeof(level_tags) / sizeof(level_tags[0]); + const char* tag = (level < n_levels) ? level_tags[level] : "???"; + + std::lock_guard guard(s->mtx); + std::string line = producer_prefix(s, producer_id); + line += '['; + line += tag; + line += "] "; + line.append(text, len); + append_line(s, std::move(line)); +} - void flush() { - std::lock_guard guard(mtx); - flush_locked(); - } +void handle_stat(FilePluginState* s, uint32_t producer_id, uint32_t stat_id, int64_t value) { + std::lock_guard guard(s->mtx); + std::string line = producer_prefix(s, producer_id); -private: - void flush_locked() { - if (!file || buffer.empty()) { - return; - } - - for (const auto& entry : buffer) { - std::fwrite(entry.data(), 1, entry.size(), file); - std::fputc('\n', file); - } - std::fflush(file); - buffer.clear(); + auto sit = s->stat_names.find({producer_id, stat_id}); + if (sit != s->stat_names.end()) { + line += "[STAT:" + sit->second + "] " + std::to_string(value); + } else { + line += "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); } -}; + append_line(s, std::move(line)); +} -State* g_state = nullptr; +void handle_stat_meta(FilePluginState* s, uint32_t producer_id, uint32_t stat_id, const char* name) { + std::lock_guard guard(s->mtx); + s->stat_names[{producer_id, stat_id}] = name; +} +// ============================================================================ +// consumer callback +// ============================================================================ void on_event(const PlexdbLogEvent* event, void* ctx) { - auto* state = static_cast(ctx); + auto* s = static_cast(ctx); switch (event->type) { - case PLEXDB_LOG_PRODUCER_REGISTERED:{ - state->on_producer_registered( + case PLEXDB_LOG_PRODUCER_REGISTERED: + handle_producer_registered(s, event->producer_registered.producer_id, event->producer_registered.name); - }break; - case PLEXDB_LOG_MESSAGE:{ - state->on_message( + break; + case PLEXDB_LOG_PRODUCER_META: + handle_producer_meta(s, + event->producer_meta.producer_id, + event->producer_meta.key, + event->producer_meta.value); + break; + case PLEXDB_LOG_MESSAGE: + handle_message(s, event->message.producer_id, event->message.level, event->message.text, event->message.text_len); - }break; - case PLEXDB_LOG_STAT:{ - state->on_stat( + break; + case PLEXDB_LOG_STAT: + handle_stat(s, event->stat.producer_id, event->stat.stat_id, event->stat.value); - }break; - case PLEXDB_LOG_STAT_META:{ - state->on_stat_meta( + break; + case PLEXDB_LOG_STAT_META: + handle_stat_meta(s, event->stat_meta.producer_id, event->stat_meta.stat_id, event->stat_meta.name); - }break; + break; + default: + break; } } +// ============================================================================ +// lifecycle +// ============================================================================ +FilePluginState* file_plugin_init() { + const char* path_cstr = std::getenv("PLEXDB_LOG_FILE"); + std::string path = (!path_cstr) ? DEFAULT_PLEXDB_LOG_FILE : std::string(path_cstr); + + size_t batch = DEFAULT_PLEXDB_LOG_BATCH; + const char* batch_env = std::getenv("PLEXDB_LOG_BATCH"); + if (batch_env) { + size_t v = static_cast(std::atol(batch_env)); + if (v > 0) batch = v; + } + + auto* s = new FilePluginState{}; + s->file = std::fopen(path.c_str(), "a"); + s->batch = batch; + return s; +} + +void file_plugin_fini(FilePluginState* s) { + if (!s) return; + flush_buffer(s); + if (s->file) std::fclose(s->file); + delete s; +} + } // namespace __attribute__((constructor)) static void init() { - g_state = new State(); + g_state = file_plugin_init(); plexdb_log_register_consumer(on_event, g_state); } __attribute__((destructor)) static void fini() { - if (!g_state) { - return; - } - + if (!g_state) return; plexdb_log_unregister_consumer(on_event, g_state); - delete g_state; + file_plugin_fini(g_state); g_state = nullptr; } diff --git a/objstore/plugins/log_stat/log_stat_plugin.cpp b/objstore/plugins/log_stat/log_stat_plugin.cpp index 6cbb53c..6a27d83 100644 --- a/objstore/plugins/log_stat/log_stat_plugin.cpp +++ b/objstore/plugins/log_stat/log_stat_plugin.cpp @@ -1,8 +1,9 @@ // Stat-logging plugin: writes structured stat events to a line-oriented text file. -// Designed for consumption by extra/plot_stats.py. +// Designed for consumption by extra/plot_stats.py or tail -f for live monitoring. // // Output format (one line per event, tab-separated): // P \t — producer registration +// D \t\t — producer metadata // M \t\t — stat metadata // S \t\t\t — stat sample // @@ -19,66 +20,69 @@ namespace { -struct State { - std::FILE* file = nullptr; +struct StatPluginState { + std::FILE* file; std::mutex mtx; +}; - State() { - const char* path_cstr = std::getenv("PLEXDB_STAT_FILE"); - std::string path = path_cstr ? std::string(path_cstr) : "plexdb.stats"; - file = std::fopen(path.c_str(), "w"); - } +StatPluginState* g_state = nullptr; - ~State() { - if (file) std::fclose(file); - } +void write_producer_registered(StatPluginState* s, uint32_t id, const char* name) { + std::lock_guard guard(s->mtx); + if (!s->file) return; + std::fprintf(s->file, "P %u\t%s\n", id, name); + std::fflush(s->file); +} - void on_producer_registered(uint32_t id, const char* name) { - std::lock_guard guard(mtx); - if (!file) return; - std::fprintf(file, "P %u\t%s\n", id, name); - std::fflush(file); - } +void write_producer_meta(StatPluginState* s, uint32_t producer_id, const char* key, const char* value) { + std::lock_guard guard(s->mtx); + if (!s->file) return; + std::fprintf(s->file, "D %u\t%s\t%s\n", producer_id, key, value); + std::fflush(s->file); +} - void on_stat_meta(uint32_t producer_id, uint32_t stat_id, const char* name) { - std::lock_guard guard(mtx); - if (!file) return; - std::fprintf(file, "M %u\t%u\t%s\n", producer_id, stat_id, name); - std::fflush(file); - } +void write_stat_meta(StatPluginState* s, uint32_t producer_id, uint32_t stat_id, const char* name) { + std::lock_guard guard(s->mtx); + if (!s->file) return; + std::fprintf(s->file, "M %u\t%u\t%s\n", producer_id, stat_id, name); + std::fflush(s->file); +} - void on_stat(uint32_t producer_id, uint32_t stat_id, int64_t value) { - using namespace std::chrono; - auto ns = duration_cast(steady_clock::now().time_since_epoch()).count(); - - std::lock_guard guard(mtx); - if (!file) return; - std::fprintf(file, "S %u\t%u\t%lld\t%lld\n", - producer_id, stat_id, - static_cast(ns), - static_cast(value)); - std::fflush(file); - } -}; +void write_stat(StatPluginState* s, uint32_t producer_id, uint32_t stat_id, int64_t value) { + using namespace std::chrono; + auto ns = duration_cast(steady_clock::now().time_since_epoch()).count(); -State* g_state = nullptr; + std::lock_guard guard(s->mtx); + if (!s->file) return; + std::fprintf(s->file, "S %u\t%u\t%lld\t%lld\n", + producer_id, stat_id, + static_cast(ns), + static_cast(value)); + std::fflush(s->file); +} void on_event(const PlexdbLogEvent* event, void* ctx) { - auto* state = static_cast(ctx); + auto* s = static_cast(ctx); switch (event->type) { case PLEXDB_LOG_PRODUCER_REGISTERED: - state->on_producer_registered( + write_producer_registered(s, event->producer_registered.producer_id, event->producer_registered.name); break; + case PLEXDB_LOG_PRODUCER_META: + write_producer_meta(s, + event->producer_meta.producer_id, + event->producer_meta.key, + event->producer_meta.value); + break; case PLEXDB_LOG_STAT_META: - state->on_stat_meta( + write_stat_meta(s, event->stat_meta.producer_id, event->stat_meta.stat_id, event->stat_meta.name); break; case PLEXDB_LOG_STAT: - state->on_stat( + write_stat(s, event->stat.producer_id, event->stat.stat_id, event->stat.value); @@ -88,11 +92,26 @@ void on_event(const PlexdbLogEvent* event, void* ctx) { } } +StatPluginState* stat_plugin_init() { + const char* path_cstr = std::getenv("PLEXDB_STAT_FILE"); + std::string path = path_cstr ? std::string(path_cstr) : "plexdb.stats"; + + auto* s = new StatPluginState{}; + s->file = std::fopen(path.c_str(), "w"); + return s; +} + +void stat_plugin_fini(StatPluginState* s) { + if (!s) return; + if (s->file) std::fclose(s->file); + delete s; +} + } // namespace __attribute__((constructor)) static void init() { - g_state = new State(); + g_state = stat_plugin_init(); plexdb_log_register_consumer(on_event, g_state); } @@ -100,6 +119,6 @@ __attribute__((destructor)) static void fini() { if (!g_state) return; plexdb_log_unregister_consumer(on_event, g_state); - delete g_state; + stat_plugin_fini(g_state); g_state = nullptr; } diff --git a/objstore/test/assert_helpers.test.cpp b/objstore/test/assert_helpers.test.cpp index cdde5e9..e76a6af 100644 --- a/objstore/test/assert_helpers.test.cpp +++ b/objstore/test/assert_helpers.test.cpp @@ -13,6 +13,7 @@ import plexdb.base; // 1. Record the failure with FAIL_CHECK (non-throwing). // 2. If PLEXDB_TEST_SCOPE() was used, longjmp back to exit the test case. // ============================================================================ + namespace { struct AssertRecovery { diff --git a/objstore/test/log_consumer.test.cpp b/objstore/test/log_consumer.test.cpp deleted file mode 100644 index 4ae3313..0000000 --- a/objstore/test/log_consumer.test.cpp +++ /dev/null @@ -1,116 +0,0 @@ -#include -#include -#include -#include -#include "log_abi.h" - -#include -#include -#include -#include - -namespace { - -struct LogBuffer { - std::vector entries; - std::map, std::string> stat_names; - std::mutex mtx; - bool active = false; - - void clear() { - std::lock_guard g(mtx); - entries.clear(); - } - - void push(const char* level, const char* text, size_t len) { - std::lock_guard g(mtx); - if (!active) return; - std::string entry = "["; - entry += level; - entry += "] "; - entry.append(text, len); - entries.push_back(std::move(entry)); - UNSCOPED_INFO(entries.back()); - } - - void push_stat(uint32_t producer_id, uint32_t stat_id, int64_t value) { - std::lock_guard g(mtx); - if (!active) return; - auto it = stat_names.find({producer_id, stat_id}); - std::string entry; - if (it != stat_names.end()) { - entry = "[STAT:" + it->second + "] " + std::to_string(value); - } else { - entry = "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); - } - entries.push_back(std::move(entry)); - UNSCOPED_INFO(entries.back()); - } - - void register_stat_name(uint32_t producer_id, uint32_t stat_id, const char* name) { - std::lock_guard g(mtx); - stat_names[{producer_id, stat_id}] = name; - } -}; - -LogBuffer g_log_buffer; - -const char* level_str(uint32_t lvl) { - switch (lvl) { - case PLEXDB_LOG_TRACE: return "TRACE"; - case PLEXDB_LOG_DEBUG: return "DEBUG"; - case PLEXDB_LOG_INFO: return "INFO"; - case PLEXDB_LOG_WARN: return "WARN"; - case PLEXDB_LOG_ERROR: return "ERROR"; - default: return "???"; - } -} - -void on_log_event(const PlexdbLogEvent* event, void* /*ctx*/) { - switch (event->type) { - case PLEXDB_LOG_MESSAGE: - g_log_buffer.push( - level_str(event->message.level), - event->message.text, - event->message.text_len); - break; - case PLEXDB_LOG_STAT: - g_log_buffer.push_stat( - event->stat.producer_id, - event->stat.stat_id, - event->stat.value); - break; - case PLEXDB_LOG_STAT_META: - g_log_buffer.register_stat_name( - event->stat_meta.producer_id, - event->stat_meta.stat_id, - event->stat_meta.name); - break; - default: - break; - } -} - -struct LogListener : Catch::EventListenerBase { - using EventListenerBase::EventListenerBase; - - void testCaseStarting(Catch::TestCaseInfo const&) override { - g_log_buffer.active = true; - g_log_buffer.clear(); - } - void testCaseEnded(Catch::TestCaseStats const&) override { - g_log_buffer.active = false; - g_log_buffer.clear(); - } -}; -CATCH_REGISTER_LISTENER(LogListener) - -// @note Static init order: consumer only sees messages fired after registration. -// Producer catch-up IS replayed (see log_abi.h load-order contract). -struct LogConsumerInstaller { - LogConsumerInstaller() { plexdb_log_register_consumer(on_log_event, nullptr); } - ~LogConsumerInstaller() { plexdb_log_unregister_consumer(on_log_event, nullptr); } -}; -static LogConsumerInstaller g_install; - -} // namespace diff --git a/objstore/test/log_consumer_helper.test.cpp b/objstore/test/log_consumer_helper.test.cpp new file mode 100644 index 0000000..f0ffa87 --- /dev/null +++ b/objstore/test/log_consumer_helper.test.cpp @@ -0,0 +1,167 @@ +#include +#include +#include +#include +#include "log_abi.h" + +#include +#include +#include +#include + +namespace { + +// ============================================================================ +// log buffer state — plain struct, manipulated by free functions +// ============================================================================ +struct LogBuffer { + std::vector entries; + std::map, std::string> stat_names; + std::map producer_names; + std::map, std::string> producer_meta; + std::mutex mtx; + bool active = false; +}; + +LogBuffer g_log_buffer; + +void log_buffer_clear(LogBuffer& lb) { + std::lock_guard g(lb.mtx); + lb.entries.clear(); +} + +void log_buffer_push_message(LogBuffer& lb, const char* level, const char* text, size_t len) { + std::lock_guard g(lb.mtx); + if (!lb.active) return; + std::string entry = "["; + entry += level; + entry += "] "; + entry.append(text, len); + lb.entries.push_back(std::move(entry)); + UNSCOPED_INFO(lb.entries.back()); +} + +void log_buffer_push_stat(LogBuffer& lb, uint32_t producer_id, uint32_t stat_id, int64_t value) { + std::lock_guard g(lb.mtx); + if (!lb.active) return; + auto it = lb.stat_names.find({producer_id, stat_id}); + std::string entry; + if (it != lb.stat_names.end()) { + entry = "[STAT:" + it->second + "] " + std::to_string(value); + } else { + entry = "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); + } + lb.entries.push_back(std::move(entry)); + UNSCOPED_INFO(lb.entries.back()); +} + +void log_buffer_register_stat_name(LogBuffer& lb, uint32_t producer_id, uint32_t stat_id, const char* name) { + std::lock_guard g(lb.mtx); + lb.stat_names[{producer_id, stat_id}] = name; +} + +void log_buffer_register_producer(LogBuffer& lb, uint32_t id, const char* name) { + std::lock_guard g(lb.mtx); + lb.producer_names[id] = name; + if (lb.active) { + std::string entry = "[PRODUCER] " + std::string(name) + " (id=" + std::to_string(id) + ")"; + lb.entries.push_back(std::move(entry)); + UNSCOPED_INFO(lb.entries.back()); + } +} + +void log_buffer_register_producer_meta(LogBuffer& lb, uint32_t producer_id, const char* key, const char* value) { + std::lock_guard g(lb.mtx); + lb.producer_meta[{producer_id, std::string(key)}] = value; + if (lb.active) { + std::string entry = "[PRODUCER_META] id=" + std::to_string(producer_id) + + " " + key + "=" + value; + lb.entries.push_back(std::move(entry)); + UNSCOPED_INFO(lb.entries.back()); + } +} + +// ============================================================================ +// level string +// ============================================================================ +const char* level_str(uint32_t lvl) { + switch (lvl) { + case PLEXDB_LOG_TRACE: return "TRACE"; + case PLEXDB_LOG_DEBUG: return "DEBUG"; + case PLEXDB_LOG_INFO: return "INFO"; + case PLEXDB_LOG_WARN: return "WARN"; + case PLEXDB_LOG_ERROR: return "ERROR"; + default: return "???"; + } +} + +// ============================================================================ +// consumer callback +// ============================================================================ +void on_log_event(const PlexdbLogEvent* event, void* /*ctx*/) { + switch (event->type) { + case PLEXDB_LOG_PRODUCER_REGISTERED: + log_buffer_register_producer( + g_log_buffer, + event->producer_registered.producer_id, + event->producer_registered.name); + break; + case PLEXDB_LOG_MESSAGE: + log_buffer_push_message( + g_log_buffer, + level_str(event->message.level), + event->message.text, + event->message.text_len); + break; + case PLEXDB_LOG_STAT: + log_buffer_push_stat( + g_log_buffer, + event->stat.producer_id, + event->stat.stat_id, + event->stat.value); + break; + case PLEXDB_LOG_STAT_META: + log_buffer_register_stat_name( + g_log_buffer, + event->stat_meta.producer_id, + event->stat_meta.stat_id, + event->stat_meta.name); + break; + case PLEXDB_LOG_PRODUCER_META: + log_buffer_register_producer_meta( + g_log_buffer, + event->producer_meta.producer_id, + event->producer_meta.key, + event->producer_meta.value); + break; + default: + break; + } +} + +// ============================================================================ +// Catch2 listener — activates/deactivates log capture per test case +// ============================================================================ +struct LogListener : Catch::EventListenerBase { + using EventListenerBase::EventListenerBase; + + void testCaseStarting(Catch::TestCaseInfo const&) override { + g_log_buffer.active = true; + log_buffer_clear(g_log_buffer); + } + void testCaseEnded(Catch::TestCaseStats const&) override { + g_log_buffer.active = false; + log_buffer_clear(g_log_buffer); + } +}; +CATCH_REGISTER_LISTENER(LogListener) + +// @note Static init order: consumer only sees messages fired after registration. +// Producer catch-up IS replayed (see log_abi.h load-order contract). +struct LogConsumerInstaller { + LogConsumerInstaller() { plexdb_log_register_consumer(on_log_event, nullptr); } + ~LogConsumerInstaller() { plexdb_log_unregister_consumer(on_log_event, nullptr); } +}; +static LogConsumerInstaller g_log_install; + +} // namespace diff --git a/plexdb/log/log.cppm b/plexdb/log/log.cppm index bf49398..da66c54 100644 --- a/plexdb/log/log.cppm +++ b/plexdb/log/log.cppm @@ -101,4 +101,13 @@ export namespace plexdb::log { dispatch(e); } } + + inline void fire_producer_meta(uint32_t producer_id, const char* key, const char* value) { + if constexpr (enabled) { + PlexdbLogEvent e{}; + e.type = PLEXDB_LOG_PRODUCER_META; + e.producer_meta = {producer_id, key, value}; + dispatch(e); + } + } } diff --git a/plexdb/log/log.test.cpp b/plexdb/log/log.test.cpp index c4ae63b..1c50061 100644 --- a/plexdb/log/log.test.cpp +++ b/plexdb/log/log.test.cpp @@ -20,12 +20,16 @@ namespace { unsigned message_count = 0; unsigned stat_count = 0; unsigned meta_count = 0; + unsigned producer_meta_count = 0; uint32_t last_level = 0; int64_t last_stat_val = 0; uint32_t last_stat_id = 0; uint32_t last_meta_producer = 0; uint32_t last_meta_stat_id = 0; const char* last_meta_name = nullptr; + uint32_t last_pmeta_producer = 0; + const char* last_pmeta_key = nullptr; + const char* last_pmeta_value = nullptr; }; void test_on_event(const PlexdbLogEvent* event, void* ctx) { @@ -46,6 +50,12 @@ namespace { c->last_meta_stat_id = event->stat_meta.stat_id; c->last_meta_name = event->stat_meta.name; break; + case PLEXDB_LOG_PRODUCER_META: + c->producer_meta_count++; + c->last_pmeta_producer = event->producer_meta.producer_id; + c->last_pmeta_key = event->producer_meta.key; + c->last_pmeta_value = event->producer_meta.value; + break; default: break; } @@ -53,9 +63,7 @@ namespace { } TEST_CASE("fire_message with log level", "[plexdb.log]") { - if constexpr (!enabled) { - SKIP("logging disabled"); - } + if constexpr (!enabled) { return; } TestConsumer tc{}; plexdb_log_register_consumer(test_on_event, &tc); @@ -84,9 +92,7 @@ TEST_CASE("fire_message with log level", "[plexdb.log]") { } TEST_CASE("fire_stat delivers structured metrics", "[plexdb.log]") { - if constexpr (!enabled) { - SKIP("logging disabled"); - } + if constexpr (!enabled) { return; } TestConsumer tc{}; plexdb_log_register_consumer(test_on_event, &tc); @@ -107,9 +113,7 @@ TEST_CASE("fire_stat delivers structured metrics", "[plexdb.log]") { } TEST_CASE("fire_stat_meta delivers metadata", "[plexdb.log]") { - if constexpr (!enabled) { - SKIP("logging disabled"); - } + if constexpr (!enabled) { return; } TestConsumer tc{}; plexdb_log_register_consumer(test_on_event, &tc); @@ -129,3 +133,25 @@ TEST_CASE("fire_stat_meta delivers metadata", "[plexdb.log]") { plexdb_log_unregister_consumer(test_on_event, &tc); } + +TEST_CASE("fire_producer_meta delivers producer metadata", "[plexdb.log]") { + if constexpr (!enabled) { return; } + + TestConsumer tc{}; + plexdb_log_register_consumer(test_on_event, &tc); + + Producer p{"test_pmeta"}; + + fire_producer_meta(p.id, "module", "pager"); + CHECK(tc.producer_meta_count == 1); + CHECK(tc.last_pmeta_producer == p.id); + CHECK(std::string(tc.last_pmeta_key) == "module"); + CHECK(std::string(tc.last_pmeta_value) == "pager"); + + fire_producer_meta(p.id, "version", "1.0"); + CHECK(tc.producer_meta_count == 2); + CHECK(std::string(tc.last_pmeta_key) == "version"); + CHECK(std::string(tc.last_pmeta_value) == "1.0"); + + plexdb_log_unregister_consumer(test_on_event, &tc); +} diff --git a/plexdb/log/log_abi.h b/plexdb/log/log_abi.h index e259918..ca30e30 100644 --- a/plexdb/log/log_abi.h +++ b/plexdb/log/log_abi.h @@ -23,6 +23,7 @@ typedef enum PlexdbLogEventType : uint32_t { PLEXDB_LOG_MESSAGE = 2, // generic string message PLEXDB_LOG_STAT = 3, // structured numeric stat PLEXDB_LOG_STAT_META = 4, // stat metadata (name for producer+stat_id pair) + PLEXDB_LOG_PRODUCER_META = 5, // producer metadata (key-value pair for a producer) } PlexdbLogEventType; typedef struct { @@ -49,6 +50,12 @@ typedef struct { const char* name; } PlexdbLogStatMeta; +typedef struct { + uint32_t producer_id; + const char* key; + const char* value; +} PlexdbLogProducerMeta; + // @note fat struct with a type tag and union payload typedef struct { uint32_t type; // PlexdbLogEventType @@ -58,6 +65,7 @@ typedef struct { PlexdbLogMessage message; PlexdbLogStat stat; PlexdbLogStatMeta stat_meta; + PlexdbLogProducerMeta producer_meta; }; } PlexdbLogEvent; diff --git a/plexdb/test/assert_helpers.test.cpp b/plexdb/test/assert_helpers.test.cpp index 4f04b03..e76a6af 100644 --- a/plexdb/test/assert_helpers.test.cpp +++ b/plexdb/test/assert_helpers.test.cpp @@ -1,15 +1,69 @@ #include +#include +#include +#include +#include import plexdb.base; -inline void catch2_assert_handler(const char* msg, const char* file_name, const char* function_name, unsigned line_number) { - FAIL("Assert failed \"" << msg << "\" at " << function_name << " in " << file_name << ":" << line_number); +// ============================================================================ +// Graceful assert recovery for Catch2 with -fno-exceptions. +// +// FAIL() calls std::terminate when exceptions are disabled. Instead we: +// 1. Record the failure with FAIL_CHECK (non-throwing). +// 2. If PLEXDB_TEST_SCOPE() was used, longjmp back to exit the test case. +// ============================================================================ + +namespace { + +struct AssertRecovery { + std::jmp_buf buf; + bool active = false; + const char* msg = nullptr; + const char* file = nullptr; + const char* func = nullptr; + unsigned line = 0; +}; + +thread_local AssertRecovery g_recovery; + +void catch2_assert_handler(const char* msg, const char* file_name, + const char* function_name, unsigned line_number) { + if (g_recovery.active) { + g_recovery.msg = msg; + g_recovery.file = file_name; + g_recovery.func = function_name; + g_recovery.line = line_number; + g_recovery.active = false; + std::longjmp(g_recovery.buf, 1); + } + FAIL_CHECK("Assert failed \"" << msg << "\" at " << function_name + << " in " << file_name << ":" << line_number); } +struct AssertListener : Catch::EventListenerBase { + using EventListenerBase::EventListenerBase; + void testCaseStarting(Catch::TestCaseInfo const&) override { g_recovery.active = false; } + void testCaseEnded(Catch::TestCaseStats const&) override { g_recovery.active = false; } +}; +CATCH_REGISTER_LISTENER(AssertListener) + struct AssertHandlerInstaller { - AssertHandlerInstaller() { - plexdb::set_assert_handler(&catch2_assert_handler); - } + AssertHandlerInstaller() { plexdb::set_assert_handler(&catch2_assert_handler); } }; +static AssertHandlerInstaller g_assert_install; + +} // namespace -static AssertHandlerInstaller install; \ No newline at end of file +// Usage: place PLEXDB_TEST_SCOPE() at the top of a TEST_CASE or SECTION body. +// If a plexdb assertion fires, the failure is recorded and the scope returns. +#define PLEXDB_TEST_SCOPE() \ + do { \ + g_recovery.active = true; \ + if (setjmp(g_recovery.buf) != 0) { \ + FAIL_CHECK("Assert failed \"" << g_recovery.msg << "\" at " \ + << g_recovery.func << " in " << g_recovery.file << ":" \ + << g_recovery.line); \ + return; \ + } \ + } while(0) \ No newline at end of file diff --git a/plexdb/test/log_consumer.test.cpp b/plexdb/test/log_consumer.test.cpp deleted file mode 100644 index 4ae3313..0000000 --- a/plexdb/test/log_consumer.test.cpp +++ /dev/null @@ -1,116 +0,0 @@ -#include -#include -#include -#include -#include "log_abi.h" - -#include -#include -#include -#include - -namespace { - -struct LogBuffer { - std::vector entries; - std::map, std::string> stat_names; - std::mutex mtx; - bool active = false; - - void clear() { - std::lock_guard g(mtx); - entries.clear(); - } - - void push(const char* level, const char* text, size_t len) { - std::lock_guard g(mtx); - if (!active) return; - std::string entry = "["; - entry += level; - entry += "] "; - entry.append(text, len); - entries.push_back(std::move(entry)); - UNSCOPED_INFO(entries.back()); - } - - void push_stat(uint32_t producer_id, uint32_t stat_id, int64_t value) { - std::lock_guard g(mtx); - if (!active) return; - auto it = stat_names.find({producer_id, stat_id}); - std::string entry; - if (it != stat_names.end()) { - entry = "[STAT:" + it->second + "] " + std::to_string(value); - } else { - entry = "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); - } - entries.push_back(std::move(entry)); - UNSCOPED_INFO(entries.back()); - } - - void register_stat_name(uint32_t producer_id, uint32_t stat_id, const char* name) { - std::lock_guard g(mtx); - stat_names[{producer_id, stat_id}] = name; - } -}; - -LogBuffer g_log_buffer; - -const char* level_str(uint32_t lvl) { - switch (lvl) { - case PLEXDB_LOG_TRACE: return "TRACE"; - case PLEXDB_LOG_DEBUG: return "DEBUG"; - case PLEXDB_LOG_INFO: return "INFO"; - case PLEXDB_LOG_WARN: return "WARN"; - case PLEXDB_LOG_ERROR: return "ERROR"; - default: return "???"; - } -} - -void on_log_event(const PlexdbLogEvent* event, void* /*ctx*/) { - switch (event->type) { - case PLEXDB_LOG_MESSAGE: - g_log_buffer.push( - level_str(event->message.level), - event->message.text, - event->message.text_len); - break; - case PLEXDB_LOG_STAT: - g_log_buffer.push_stat( - event->stat.producer_id, - event->stat.stat_id, - event->stat.value); - break; - case PLEXDB_LOG_STAT_META: - g_log_buffer.register_stat_name( - event->stat_meta.producer_id, - event->stat_meta.stat_id, - event->stat_meta.name); - break; - default: - break; - } -} - -struct LogListener : Catch::EventListenerBase { - using EventListenerBase::EventListenerBase; - - void testCaseStarting(Catch::TestCaseInfo const&) override { - g_log_buffer.active = true; - g_log_buffer.clear(); - } - void testCaseEnded(Catch::TestCaseStats const&) override { - g_log_buffer.active = false; - g_log_buffer.clear(); - } -}; -CATCH_REGISTER_LISTENER(LogListener) - -// @note Static init order: consumer only sees messages fired after registration. -// Producer catch-up IS replayed (see log_abi.h load-order contract). -struct LogConsumerInstaller { - LogConsumerInstaller() { plexdb_log_register_consumer(on_log_event, nullptr); } - ~LogConsumerInstaller() { plexdb_log_unregister_consumer(on_log_event, nullptr); } -}; -static LogConsumerInstaller g_install; - -} // namespace diff --git a/plexdb/test/log_consumer_helper.test.cpp b/plexdb/test/log_consumer_helper.test.cpp new file mode 100644 index 0000000..f0ffa87 --- /dev/null +++ b/plexdb/test/log_consumer_helper.test.cpp @@ -0,0 +1,167 @@ +#include +#include +#include +#include +#include "log_abi.h" + +#include +#include +#include +#include + +namespace { + +// ============================================================================ +// log buffer state — plain struct, manipulated by free functions +// ============================================================================ +struct LogBuffer { + std::vector entries; + std::map, std::string> stat_names; + std::map producer_names; + std::map, std::string> producer_meta; + std::mutex mtx; + bool active = false; +}; + +LogBuffer g_log_buffer; + +void log_buffer_clear(LogBuffer& lb) { + std::lock_guard g(lb.mtx); + lb.entries.clear(); +} + +void log_buffer_push_message(LogBuffer& lb, const char* level, const char* text, size_t len) { + std::lock_guard g(lb.mtx); + if (!lb.active) return; + std::string entry = "["; + entry += level; + entry += "] "; + entry.append(text, len); + lb.entries.push_back(std::move(entry)); + UNSCOPED_INFO(lb.entries.back()); +} + +void log_buffer_push_stat(LogBuffer& lb, uint32_t producer_id, uint32_t stat_id, int64_t value) { + std::lock_guard g(lb.mtx); + if (!lb.active) return; + auto it = lb.stat_names.find({producer_id, stat_id}); + std::string entry; + if (it != lb.stat_names.end()) { + entry = "[STAT:" + it->second + "] " + std::to_string(value); + } else { + entry = "[STAT] id=" + std::to_string(stat_id) + " value=" + std::to_string(value); + } + lb.entries.push_back(std::move(entry)); + UNSCOPED_INFO(lb.entries.back()); +} + +void log_buffer_register_stat_name(LogBuffer& lb, uint32_t producer_id, uint32_t stat_id, const char* name) { + std::lock_guard g(lb.mtx); + lb.stat_names[{producer_id, stat_id}] = name; +} + +void log_buffer_register_producer(LogBuffer& lb, uint32_t id, const char* name) { + std::lock_guard g(lb.mtx); + lb.producer_names[id] = name; + if (lb.active) { + std::string entry = "[PRODUCER] " + std::string(name) + " (id=" + std::to_string(id) + ")"; + lb.entries.push_back(std::move(entry)); + UNSCOPED_INFO(lb.entries.back()); + } +} + +void log_buffer_register_producer_meta(LogBuffer& lb, uint32_t producer_id, const char* key, const char* value) { + std::lock_guard g(lb.mtx); + lb.producer_meta[{producer_id, std::string(key)}] = value; + if (lb.active) { + std::string entry = "[PRODUCER_META] id=" + std::to_string(producer_id) + + " " + key + "=" + value; + lb.entries.push_back(std::move(entry)); + UNSCOPED_INFO(lb.entries.back()); + } +} + +// ============================================================================ +// level string +// ============================================================================ +const char* level_str(uint32_t lvl) { + switch (lvl) { + case PLEXDB_LOG_TRACE: return "TRACE"; + case PLEXDB_LOG_DEBUG: return "DEBUG"; + case PLEXDB_LOG_INFO: return "INFO"; + case PLEXDB_LOG_WARN: return "WARN"; + case PLEXDB_LOG_ERROR: return "ERROR"; + default: return "???"; + } +} + +// ============================================================================ +// consumer callback +// ============================================================================ +void on_log_event(const PlexdbLogEvent* event, void* /*ctx*/) { + switch (event->type) { + case PLEXDB_LOG_PRODUCER_REGISTERED: + log_buffer_register_producer( + g_log_buffer, + event->producer_registered.producer_id, + event->producer_registered.name); + break; + case PLEXDB_LOG_MESSAGE: + log_buffer_push_message( + g_log_buffer, + level_str(event->message.level), + event->message.text, + event->message.text_len); + break; + case PLEXDB_LOG_STAT: + log_buffer_push_stat( + g_log_buffer, + event->stat.producer_id, + event->stat.stat_id, + event->stat.value); + break; + case PLEXDB_LOG_STAT_META: + log_buffer_register_stat_name( + g_log_buffer, + event->stat_meta.producer_id, + event->stat_meta.stat_id, + event->stat_meta.name); + break; + case PLEXDB_LOG_PRODUCER_META: + log_buffer_register_producer_meta( + g_log_buffer, + event->producer_meta.producer_id, + event->producer_meta.key, + event->producer_meta.value); + break; + default: + break; + } +} + +// ============================================================================ +// Catch2 listener — activates/deactivates log capture per test case +// ============================================================================ +struct LogListener : Catch::EventListenerBase { + using EventListenerBase::EventListenerBase; + + void testCaseStarting(Catch::TestCaseInfo const&) override { + g_log_buffer.active = true; + log_buffer_clear(g_log_buffer); + } + void testCaseEnded(Catch::TestCaseStats const&) override { + g_log_buffer.active = false; + log_buffer_clear(g_log_buffer); + } +}; +CATCH_REGISTER_LISTENER(LogListener) + +// @note Static init order: consumer only sees messages fired after registration. +// Producer catch-up IS replayed (see log_abi.h load-order contract). +struct LogConsumerInstaller { + LogConsumerInstaller() { plexdb_log_register_consumer(on_log_event, nullptr); } + ~LogConsumerInstaller() { plexdb_log_unregister_consumer(on_log_event, nullptr); } +}; +static LogConsumerInstaller g_log_install; + +} // namespace From df078b3fe5bcce8cedd2668dd292f61baed002bd Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 19 Mar 2026 10:02:18 +0000 Subject: [PATCH 07/10] Address code review: fix filename references and comment capitalization Co-authored-by: patricklbell <46551885+patricklbell@users.noreply.github.com> --- .github/instructions/tests.instructions.md | 2 +- AGENTS.md | 2 +- objstore/test/log_consumer_helper.test.cpp | 2 +- plexdb/test/log_consumer_helper.test.cpp | 2 +- 4 files changed, 4 insertions(+), 4 deletions(-) diff --git a/.github/instructions/tests.instructions.md b/.github/instructions/tests.instructions.md index 97a1aa4..f57f48c 100644 --- a/.github/instructions/tests.instructions.md +++ b/.github/instructions/tests.instructions.md @@ -35,7 +35,7 @@ TEST_CASE("descriptive name", "[tag]") { ## Debugging Test Failures - Build with `-DPLEXDB_LOG_ENABLED=ON` so log messages appear in failing tests. -- All `plexdb::log` messages are routed to Catch2 `UNSCOPED_INFO` by the test log consumer (`test/log_consumer.test.cpp`). When a test fails, all log messages emitted during that test case are printed alongside the failure. +- All `plexdb::log` messages are routed to Catch2 `UNSCOPED_INFO` by the test log consumer (`test/log_consumer_helper.test.cpp`). When a test fails, all log messages emitted during that test case are printed alongside the failure. - To add diagnostic logging in production code, use `plexdb::log::fire_message(producer.id, Level::Debug, text, len)`. This is zero-overhead when logging is disabled at build time. - For numeric metrics without string formatting overhead, use `plexdb::log::fire_stat(producer.id, stat_id, value)`. - Register stat metadata with `plexdb::log::fire_stat_meta(producer.id, stat_id, "name")` so consumers display human-readable stat names on failure. diff --git a/AGENTS.md b/AGENTS.md index 4b86255..adfc5ce 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -18,7 +18,7 @@ ## Logging & debugging test failures - Build with `-DPLEXDB_LOG_ENABLED=ON` to enable the structured logging system. -- All log messages are routed to Catch2's `UNSCOPED_INFO` via the test log consumer (`test/log_consumer.test.cpp`). They appear automatically in the output of any failing test case. +- All log messages are routed to Catch2's `UNSCOPED_INFO` via the test log consumer (`test/log_consumer_helper.test.cpp`). They appear automatically in the output of any failing test case. - The log system uses levels: `Trace`, `Debug`, `Info`, `Warn`, `Error` (see `plexdb::log::Level`). - To add diagnostic logging, create a `plexdb::log::Producer` and call `plexdb::log::fire_message(producer.id, Level::Debug, text, len)`. - For structured numeric metrics use `plexdb::log::fire_stat(producer.id, stat_id, value)` — no string formatting overhead. diff --git a/objstore/test/log_consumer_helper.test.cpp b/objstore/test/log_consumer_helper.test.cpp index f0ffa87..83cda11 100644 --- a/objstore/test/log_consumer_helper.test.cpp +++ b/objstore/test/log_consumer_helper.test.cpp @@ -157,7 +157,7 @@ struct LogListener : Catch::EventListenerBase { CATCH_REGISTER_LISTENER(LogListener) // @note Static init order: consumer only sees messages fired after registration. -// Producer catch-up IS replayed (see log_abi.h load-order contract). +// Producer catch-up is replayed (see log_abi.h load-order contract). struct LogConsumerInstaller { LogConsumerInstaller() { plexdb_log_register_consumer(on_log_event, nullptr); } ~LogConsumerInstaller() { plexdb_log_unregister_consumer(on_log_event, nullptr); } diff --git a/plexdb/test/log_consumer_helper.test.cpp b/plexdb/test/log_consumer_helper.test.cpp index f0ffa87..83cda11 100644 --- a/plexdb/test/log_consumer_helper.test.cpp +++ b/plexdb/test/log_consumer_helper.test.cpp @@ -157,7 +157,7 @@ struct LogListener : Catch::EventListenerBase { CATCH_REGISTER_LISTENER(LogListener) // @note Static init order: consumer only sees messages fired after registration. -// Producer catch-up IS replayed (see log_abi.h load-order contract). +// Producer catch-up is replayed (see log_abi.h load-order contract). struct LogConsumerInstaller { LogConsumerInstaller() { plexdb_log_register_consumer(on_log_event, nullptr); } ~LogConsumerInstaller() { plexdb_log_unregister_consumer(on_log_event, nullptr); } From b078e6a8580e1b4309d23f44697a2d118351a552 Mon Sep 17 00:00:00 2001 From: patricklbell <46551885+patricklbell@users.noreply.github.com> Date: Fri, 20 Mar 2026 00:11:12 +1100 Subject: [PATCH 08/10] renamed --- objstore/CMakeLists.txt | 2 +- .../test/{assert_helpers.test.cpp => assert.helper.test.cpp} | 0 ...og_consumer_helper.test.cpp => log_consumer.helper.test.cpp} | 0 ...rter.helper.cppm => parsers_error_reporter.helper.test.cppm} | 0 4 files changed, 1 insertion(+), 1 deletion(-) rename objstore/test/{assert_helpers.test.cpp => assert.helper.test.cpp} (100%) rename objstore/test/{log_consumer_helper.test.cpp => log_consumer.helper.test.cpp} (100%) rename objstore/test/{parsers_error_reporter.helper.cppm => parsers_error_reporter.helper.test.cppm} (100%) diff --git a/objstore/CMakeLists.txt b/objstore/CMakeLists.txt index 917ba3f..0cd730b 100644 --- a/objstore/CMakeLists.txt +++ b/objstore/CMakeLists.txt @@ -207,7 +207,7 @@ if(BUILD_TESTS) "${CMAKE_CURRENT_SOURCE_DIR}/**/*.test.cpp" ) file(GLOB_RECURSE OBJSTORE_TEST_MODULE_SOURCES CONFIGURE_DEPENDS - "${CMAKE_CURRENT_SOURCE_DIR}/**/*.helper.cppm" + "${CMAKE_CURRENT_SOURCE_DIR}/**/*.test.cppm" ) target_sources(objstore_tests PRIVATE diff --git a/objstore/test/assert_helpers.test.cpp b/objstore/test/assert.helper.test.cpp similarity index 100% rename from objstore/test/assert_helpers.test.cpp rename to objstore/test/assert.helper.test.cpp diff --git a/objstore/test/log_consumer_helper.test.cpp b/objstore/test/log_consumer.helper.test.cpp similarity index 100% rename from objstore/test/log_consumer_helper.test.cpp rename to objstore/test/log_consumer.helper.test.cpp diff --git a/objstore/test/parsers_error_reporter.helper.cppm b/objstore/test/parsers_error_reporter.helper.test.cppm similarity index 100% rename from objstore/test/parsers_error_reporter.helper.cppm rename to objstore/test/parsers_error_reporter.helper.test.cppm From b809ccde2fdfb9088c03a937348fa3fc0b008f35 Mon Sep 17 00:00:00 2001 From: patricklbell <46551885+patricklbell@users.noreply.github.com> Date: Fri, 20 Mar 2026 22:41:00 +1100 Subject: [PATCH 09/10] OTel support for stats/logs rather than adhoc --- .github/instructions/tests.instructions.md | 8 +- AGENTS.md | 10 +- extra/grafana/dashboards/plexdb.json | 214 +++++++++++++ .../provisioning/dashboards/dashboard.yml | 12 + .../provisioning/datasources/datasource.yml | 9 + extra/otel-config.yaml | 22 ++ extra/otlp-docker-compose.yml | 38 +++ extra/plot_stats.py | 197 ------------ extra/prometheus.yml | 7 + objstore/CMakeLists.txt | 46 +-- objstore/entry/main.cpp | 2 +- objstore/log/log.cpp | 45 ++- objstore/log/log.cppm | 10 +- objstore/native/native.cppm | 7 + objstore/parsers/parsers.cpp | 25 +- objstore/parsers/parsers.cppm | 4 +- objstore/parsers/parsers.test.cpp | 207 ++++++------- .../log_dashboard/log_dashboard_plugin.cpp | 237 -------------- objstore/plugins/log_file/.gitignore | 1 + objstore/plugins/log_file/CMakeLists.txt | 15 + objstore/plugins/log_file/log_file_plugin.cpp | 23 +- objstore/plugins/log_otel/.gitignore | 1 + objstore/plugins/log_otel/CMakeLists.txt | 54 ++++ objstore/plugins/log_otel/INSTALL.md | 3 + objstore/plugins/log_otel/log_otel_plugin.cpp | 293 ++++++++++++++++++ objstore/plugins/log_stat/log_stat_plugin.cpp | 124 -------- objstore/repl/repl.cpp | 2 +- objstore/tcp/tcp.detail.cppm | 9 + objstore/test/assert.helper.test.cpp | 4 +- objstore/test/log_consumer.helper.test.cpp | 2 - .../parsers_error_reporter.helper.test.cppm | 9 - plexdb/CMakeLists.txt | 4 +- plexdb/log/log.cpp | 50 ++- plexdb/log/log.cppm | 108 +++++-- plexdb/log/log.test.cpp | 142 ++++++--- plexdb/log/log_abi.h | 17 +- plexdb/os/os.cppm | 3 +- plexdb/os/time.cpp | 17 + plexdb/os/time.cppm | 7 + 39 files changed, 1129 insertions(+), 859 deletions(-) create mode 100644 extra/grafana/dashboards/plexdb.json create mode 100644 extra/grafana/provisioning/dashboards/dashboard.yml create mode 100644 extra/grafana/provisioning/datasources/datasource.yml create mode 100644 extra/otel-config.yaml create mode 100644 extra/otlp-docker-compose.yml delete mode 100644 extra/plot_stats.py create mode 100644 extra/prometheus.yml delete mode 100644 objstore/plugins/log_dashboard/log_dashboard_plugin.cpp create mode 100644 objstore/plugins/log_file/.gitignore create mode 100644 objstore/plugins/log_file/CMakeLists.txt create mode 100644 objstore/plugins/log_otel/.gitignore create mode 100644 objstore/plugins/log_otel/CMakeLists.txt create mode 100644 objstore/plugins/log_otel/INSTALL.md create mode 100644 objstore/plugins/log_otel/log_otel_plugin.cpp delete mode 100644 objstore/plugins/log_stat/log_stat_plugin.cpp delete mode 100644 objstore/test/parsers_error_reporter.helper.test.cppm create mode 100644 plexdb/os/time.cpp create mode 100644 plexdb/os/time.cppm diff --git a/.github/instructions/tests.instructions.md b/.github/instructions/tests.instructions.md index f57f48c..081e58c 100644 --- a/.github/instructions/tests.instructions.md +++ b/.github/instructions/tests.instructions.md @@ -36,11 +36,11 @@ TEST_CASE("descriptive name", "[tag]") { ## Debugging Test Failures - Build with `-DPLEXDB_LOG_ENABLED=ON` so log messages appear in failing tests. - All `plexdb::log` messages are routed to Catch2 `UNSCOPED_INFO` by the test log consumer (`test/log_consumer_helper.test.cpp`). When a test fails, all log messages emitted during that test case are printed alongside the failure. -- To add diagnostic logging in production code, use `plexdb::log::fire_message(producer.id, Level::Debug, text, len)`. This is zero-overhead when logging is disabled at build time. -- For numeric metrics without string formatting overhead, use `plexdb::log::fire_stat(producer.id, stat_id, value)`. -- Register stat metadata with `plexdb::log::fire_stat_meta(producer.id, stat_id, "name")` so consumers display human-readable stat names on failure. +- To add diagnostic logging in production code, create a `plexdb::log::Producer` and use `plexdb::log::message(producer, Level::Debug, str8)` where `str8` is a `String8`. This is zero-overhead when logging is disabled at build time. Registration is lazy — the producer registers itself on first use. +- For numeric metrics without string formatting overhead, create a `plexdb::log::Stat` with a `StatType` (`Counter` or `Gauge`) and use `plexdb::log::stat(s, value)`. The stat's name and type are registered automatically on first fire. Default type is `Gauge`. +- When a consumer registers, all known producers and stat metadata are replayed (catch-up). - Custom log consumers can be registered via the plugin ABI (`plexdb_log_register_consumer` in `plexdb/log/log_abi.h`). Write a consumer to filter by producer ID, log level, or stat ID. -- The stat plugin (`objstore/plugins/log_stat/log_stat_plugin.cpp`) writes stat events to a file. Graph them with `python extra/plot_stats.py plexdb.stats`. +- The OTLP plugin (`objstore/plugins/log_otel/log_otel_plugin.cpp`) exports metrics via OpenTelemetry (OTLP/HTTP JSON). - Parse errors are reported via `UNSCOPED_INFO` through `objstore/test/parsers_error_reporter.helper.cppm` and also through the log system (`objstore::log::cql_parse_error` at `Level::Error`). ## Benchmarks diff --git a/AGENTS.md b/AGENTS.md index adfc5ce..4744d35 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -20,8 +20,10 @@ - Build with `-DPLEXDB_LOG_ENABLED=ON` to enable the structured logging system. - All log messages are routed to Catch2's `UNSCOPED_INFO` via the test log consumer (`test/log_consumer_helper.test.cpp`). They appear automatically in the output of any failing test case. - The log system uses levels: `Trace`, `Debug`, `Info`, `Warn`, `Error` (see `plexdb::log::Level`). -- To add diagnostic logging, create a `plexdb::log::Producer` and call `plexdb::log::fire_message(producer.id, Level::Debug, text, len)`. -- For structured numeric metrics use `plexdb::log::fire_stat(producer.id, stat_id, value)` — no string formatting overhead. -- Register stat metadata with `plexdb::log::fire_stat_meta(producer.id, stat_id, "name")` so consumers can map stat IDs to human-readable names. +- Registration is lazy: `Producer` and `Stat` objects register themselves on first use, so construction order does not matter. +- To add diagnostic logging, create a `plexdb::log::Producer` and call `plexdb::log::message(producer, Level::Debug, str8)` where `str8` is a `String8`. +- For structured numeric metrics, create a `plexdb::log::Stat` with a `StatType` (`Counter` or `Gauge`) and call `plexdb::log::stat(s, value)` — no string formatting overhead. The stat's name and type are registered automatically on first fire. +- Stat types: `StatType::Counter` for monotonically increasing cumulative values, `StatType::Gauge` for point-in-time measurements. Default is `Gauge`. +- When a consumer registers, all known producers and stat metadata (including stat types) are replayed (catch-up), so the consumer always has a complete view. - The plugin system (`plexdb/log/log_abi.h`) allows custom consumers. Register via `plexdb_log_register_consumer` to filter or redirect logs. See `objstore/plugins/log_file/log_file_plugin.cpp` for a reference plugin. -- The stat plugin (`objstore/plugins/log_stat/log_stat_plugin.cpp`) writes stat events to a file. Graph them with `python extra/plot_stats.py plexdb.stats`. \ No newline at end of file +- The OTLP plugin (`objstore/plugins/log_otel/log_otel_plugin.cpp`) exports metrics via OpenTelemetry (OTLP/HTTP JSON). \ No newline at end of file diff --git a/extra/grafana/dashboards/plexdb.json b/extra/grafana/dashboards/plexdb.json new file mode 100644 index 0000000..5c0b2af --- /dev/null +++ b/extra/grafana/dashboards/plexdb.json @@ -0,0 +1,214 @@ +{ + "annotations": { "list": [] }, + "editable": true, + "fiscalYearStartMonth": 0, + "graphTooltip": 1, + "id": null, + "links": [], + "panels": [ + { + "title": "Active Connections", + "type": "timeseries", + "gridPos": { "h": 8, "w": 12, "x": 0, "y": 0 }, + "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, + "fieldConfig": { + "defaults": { + "color": { "mode": "palette-classic" }, + "custom": { + "fillOpacity": 10, + "lineWidth": 2, + "pointSize": 5, + "showPoints": "auto" + }, + "unit": "short" + }, + "overrides": [] + }, + "options": { + "legend": { "displayMode": "list", "placement": "bottom" }, + "tooltip": { "mode": "single" } + }, + "targets": [ + { + "expr": "db_client_connection_count", + "legendFormat": "active connections", + "refId": "A" + } + ] + }, + { + "title": "Max Connections", + "type": "stat", + "gridPos": { "h": 8, "w": 6, "x": 12, "y": 0 }, + "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, + "fieldConfig": { + "defaults": { + "color": { "mode": "thresholds" }, + "thresholds": { + "steps": [ + { "color": "green", "value": null }, + { "color": "yellow", "value": 80 }, + { "color": "red", "value": 100 } + ] + }, + "unit": "short" + }, + "overrides": [] + }, + "options": { + "colorMode": "value", + "graphMode": "area", + "reduceOptions": { "calcs": ["lastNotNull"] } + }, + "targets": [ + { + "expr": "db_client_connection_max", + "legendFormat": "max", + "refId": "A" + } + ] + }, + { + "title": "Connection Utilization", + "type": "gauge", + "gridPos": { "h": 8, "w": 6, "x": 18, "y": 0 }, + "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, + "fieldConfig": { + "defaults": { + "color": { "mode": "thresholds" }, + "thresholds": { + "steps": [ + { "color": "green", "value": null }, + { "color": "yellow", "value": 60 }, + { "color": "red", "value": 90 } + ] + }, + "min": 0, + "max": 100, + "unit": "percent" + }, + "overrides": [] + }, + "options": { + "reduceOptions": { "calcs": ["lastNotNull"] } + }, + "targets": [ + { + "expr": "db_client_connection_count / db_client_connection_max * 100", + "legendFormat": "utilization", + "refId": "A" + } + ] + }, + { + "title": "Operation Duration", + "type": "timeseries", + "gridPos": { "h": 8, "w": 12, "x": 0, "y": 8 }, + "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, + "fieldConfig": { + "defaults": { + "color": { "mode": "palette-classic" }, + "custom": { + "fillOpacity": 10, + "lineWidth": 2, + "pointSize": 5, + "showPoints": "auto" + }, + "unit": "\u00b5s" + }, + "overrides": [] + }, + "options": { + "legend": { "displayMode": "list", "placement": "bottom" }, + "tooltip": { "mode": "single" } + }, + "targets": [ + { + "expr": "db_client_operation_duration", + "legendFormat": "duration (\u00b5s)", + "refId": "A" + } + ] + }, + { + "title": "Returned Rows", + "type": "timeseries", + "gridPos": { "h": 8, "w": 12, "x": 12, "y": 8 }, + "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, + "fieldConfig": { + "defaults": { + "color": { "mode": "palette-classic" }, + "custom": { + "fillOpacity": 10, + "lineWidth": 2, + "pointSize": 5, + "showPoints": "auto" + }, + "unit": "short" + }, + "overrides": [] + }, + "options": { + "legend": { "displayMode": "list", "placement": "bottom" }, + "tooltip": { "mode": "single" } + }, + "targets": [ + { + "expr": "db_client_response_returned_rows", + "legendFormat": "returned rows", + "refId": "A" + } + ] + }, + { + "title": "All Metrics (auto-discovery)", + "type": "timeseries", + "gridPos": { "h": 8, "w": 24, "x": 0, "y": 16 }, + "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, + "fieldConfig": { + "defaults": { + "color": { "mode": "palette-classic" }, + "custom": { + "fillOpacity": 10, + "lineWidth": 2 + } + }, + "overrides": [] + }, + "options": { + "legend": { "displayMode": "list", "placement": "bottom" }, + "tooltip": { "mode": "multi" } + }, + "targets": [ + { + "expr": "{job=\"otel-collector\", __name__=~\"db_.*\"}", + "legendFormat": "{{__name__}}", + "refId": "A" + } + ] + } + ], + "schemaVersion": 39, + "templating": { + "list": [ + { + "current": { "selected": false, "text": "Prometheus", "value": "Prometheus" }, + "hide": 0, + "includeAll": false, + "label": "Datasource", + "name": "DS_PROMETHEUS", + "options": [], + "query": "prometheus", + "refresh": 1, + "type": "datasource" + } + ] + }, + "time": { "from": "now-15m", "to": "now" }, + "timepicker": {}, + "timezone": "browser", + "title": "plexdb", + "uid": "plexdb-overview", + "version": 1, + "refresh": "5s" +} diff --git a/extra/grafana/provisioning/dashboards/dashboard.yml b/extra/grafana/provisioning/dashboards/dashboard.yml new file mode 100644 index 0000000..ded14e6 --- /dev/null +++ b/extra/grafana/provisioning/dashboards/dashboard.yml @@ -0,0 +1,12 @@ +apiVersion: 1 + +providers: + - name: plexdb + orgId: 1 + folder: "" + type: file + disableDeletion: false + editable: true + options: + path: /var/lib/grafana/dashboards + foldersFromFilesStructure: false diff --git a/extra/grafana/provisioning/datasources/datasource.yml b/extra/grafana/provisioning/datasources/datasource.yml new file mode 100644 index 0000000..1a57b69 --- /dev/null +++ b/extra/grafana/provisioning/datasources/datasource.yml @@ -0,0 +1,9 @@ +apiVersion: 1 + +datasources: + - name: Prometheus + type: prometheus + access: proxy + url: http://prometheus:9090 + isDefault: true + editable: true diff --git a/extra/otel-config.yaml b/extra/otel-config.yaml new file mode 100644 index 0000000..4e70d91 --- /dev/null +++ b/extra/otel-config.yaml @@ -0,0 +1,22 @@ +receivers: + otlp: + protocols: + grpc: + endpoint: "0.0.0.0:4317" + http: + endpoint: "0.0.0.0:4318" + +exporters: + prometheus: + endpoint: "0.0.0.0:9464" + debug: + verbosity: basic + +service: + pipelines: + metrics: + receivers: [otlp] + exporters: [prometheus] + logs: + receivers: [otlp] + exporters: [debug] \ No newline at end of file diff --git a/extra/otlp-docker-compose.yml b/extra/otlp-docker-compose.yml new file mode 100644 index 0000000..ee6edc2 --- /dev/null +++ b/extra/otlp-docker-compose.yml @@ -0,0 +1,38 @@ +version: "3.9" + +services: + otel-collector: + image: otel/opentelemetry-collector-contrib:latest + container_name: otel-collector + command: ["--config=/etc/otel/config.yaml"] + volumes: + - ./otel-config.yaml:/etc/otel/config.yaml + ports: + - "4317:4317" # OTLP gRPC + - "4318:4318" # OTLP HTTP + - "9464:9464" # Prometheus metrics export + depends_on: + - prometheus + + prometheus: + image: prom/prometheus:latest + container_name: prometheus + volumes: + - ./prometheus.yml:/etc/prometheus/prometheus.yml + ports: + - "9090:9090" + + grafana: + image: grafana/grafana-oss:latest + container_name: grafana + ports: + - "3000:3000" + environment: + - GF_SECURITY_ADMIN_PASSWORD=admin + volumes: + - grafana-data:/var/lib/grafana + - ./grafana/provisioning:/etc/grafana/provisioning + - ./grafana/dashboards:/var/lib/grafana/dashboards + +volumes: + grafana-data: \ No newline at end of file diff --git a/extra/plot_stats.py b/extra/plot_stats.py deleted file mode 100644 index 90a4475..0000000 --- a/extra/plot_stats.py +++ /dev/null @@ -1,197 +0,0 @@ -#!/usr/bin/env python3 -"""Plot stats from the plexdb log_stat plugin output. - -Usage: - python extra/plot_stats.py [plexdb.stats] # static plot - python extra/plot_stats.py --live [plexdb.stats] # real-time terminal view - -The input file is produced by the objstore_log_stat plugin. Set the -environment variable PLEXDB_STAT_FILE to control the output path -(default: plexdb.stats), then load the plugin via LD_PRELOAD: - - PLEXDB_STAT_FILE=my.stats LD_PRELOAD=./build/objstore/libobjstore_log_stat.so \\ - ./build/objstore/objstore_server ... - python extra/plot_stats.py my.stats - -For the real-time terminal dashboard, prefer the native C++ dashboard plugin: - LD_PRELOAD=./build/objstore/libobjstore_log_dashboard.so \\ - ./build/objstore/objstore_server ... - -File format (tab-separated, one event per line): - P \\t — producer registration - D \\t\\t — producer metadata - M \\t\\t — stat metadata - S \\t\\t\\t — stat sample -""" - -import sys -import os -import time -import collections -from pathlib import Path - - -def parse_stats(path): - """Parse a plexdb .stats file into structured data.""" - producers = {} # producer_id -> name - producer_meta = {} # (producer_id, key) -> value - stat_meta = {} # (producer_id, stat_id) -> name - # series key = (producer_id, stat_id) - series = collections.defaultdict(lambda: {"ts": [], "values": []}) - - with open(path) as f: - for line in f: - line = line.rstrip("\n") - if not line: - continue - tag = line[0] - rest = line[2:] # skip "X " - parts = rest.split("\t") - - if tag == "P" and len(parts) >= 2: - pid = int(parts[0]) - producers[pid] = parts[1] - - elif tag == "D" and len(parts) >= 3: - pid = int(parts[0]) - producer_meta[(pid, parts[1])] = parts[2] - - elif tag == "M" and len(parts) >= 3: - pid = int(parts[0]) - sid = int(parts[1]) - stat_meta[(pid, sid)] = parts[2] - - elif tag == "S" and len(parts) >= 4: - pid = int(parts[0]) - sid = int(parts[1]) - ts_ns = int(parts[2]) - value = int(parts[3]) - key = (pid, sid) - series[key]["ts"].append(ts_ns) - series[key]["values"].append(value) - - return producers, producer_meta, stat_meta, series - - -def label_for(producers, stat_meta, key): - """Build a human-readable label for a series key.""" - pid, sid = key - producer = producers.get(pid, f"producer:{pid}") - stat = stat_meta.get(key, f"stat:{sid}") - return f"{producer} / {stat}" - - -def render_live(path): - """Tail the stats file and render a real-time terminal dashboard.""" - last_pos = 0 - producers = {} - producer_meta = {} - stat_meta = {} - stat_values = {} - - while True: - try: - with open(path) as f: - f.seek(last_pos) - new_lines = f.readlines() - last_pos = f.tell() - except FileNotFoundError: - time.sleep(0.5) - continue - - for raw in new_lines: - line = raw.rstrip("\n") - if not line: - continue - tag = line[0] - rest = line[2:] - parts = rest.split("\t") - - if tag == "P" and len(parts) >= 2: - producers[int(parts[0])] = parts[1] - elif tag == "D" and len(parts) >= 3: - producer_meta[(int(parts[0]), parts[1])] = parts[2] - elif tag == "M" and len(parts) >= 3: - stat_meta[(int(parts[0]), int(parts[1]))] = parts[2] - elif tag == "S" and len(parts) >= 4: - stat_values[(int(parts[0]), int(parts[1]))] = int(parts[3]) - - # render - sys.stdout.write("\033[H\033[2J") - sys.stdout.write("\033[1;36m=== plexdb stats (live) ===\033[0m\n\n") - - by_producer = collections.defaultdict(list) - for key in sorted(stat_values): - by_producer[key[0]].append(key) - - for pid, keys in by_producer.items(): - pname = producers.get(pid, f"producer:{pid}") - meta_str = " ".join( - f"\033[2m{k}={v}\033[0m" - for (mid, k), v in sorted(producer_meta.items()) - if mid == pid - ) - sys.stdout.write(f" \033[1;33m{pname}\033[0m (id={pid}) {meta_str}\n") - for key in keys: - sname = stat_meta.get(key, f"stat:{key[1]}") - val = stat_values[key] - sys.stdout.write(f" {sname:<30s} \033[1;32m{val}\033[0m\n") - sys.stdout.write("\n") - - if not stat_values: - sys.stdout.write(" \033[2m(waiting for stats...)\033[0m\n") - - sys.stdout.flush() - time.sleep(0.5) - - -def plot_static(path): - """Static matplotlib plot.""" - producers, producer_meta, stat_meta, series = parse_stats(path) - - if not series: - print("No stat samples found in", path) - sys.exit(0) - - try: - import matplotlib.pyplot as plt - except ImportError: - print("error: matplotlib is required. pip install matplotlib", file=sys.stderr) - sys.exit(1) - - fig, ax = plt.subplots(figsize=(12, 6)) - - for key, data in sorted(series.items()): - ts = data["ts"] - vals = data["values"] - t0 = ts[0] - t_sec = [(t - t0) / 1e9 for t in ts] - ax.plot(t_sec, vals, label=label_for(producers, stat_meta, key), marker=".", markersize=3) - - ax.set_xlabel("Time (seconds)") - ax.set_ylabel("Value") - ax.set_title("plexdb stats") - ax.legend(loc="best", fontsize="small") - ax.grid(True, alpha=0.3) - fig.tight_layout() - plt.show() - - -def main(): - live = "--live" in sys.argv - args = [a for a in sys.argv[1:] if a != "--live"] - path = args[0] if args else "plexdb.stats" - - if not live and not Path(path).exists(): - print(f"error: file not found: {path}", file=sys.stderr) - print(__doc__, file=sys.stderr) - sys.exit(1) - - if live: - render_live(path) - else: - plot_static(path) - - -if __name__ == "__main__": - main() diff --git a/extra/prometheus.yml b/extra/prometheus.yml new file mode 100644 index 0000000..63d326b --- /dev/null +++ b/extra/prometheus.yml @@ -0,0 +1,7 @@ +global: + scrape_interval: 5s + +scrape_configs: + - job_name: "otel-collector" + static_configs: + - targets: ["otel-collector:9464"] \ No newline at end of file diff --git a/objstore/CMakeLists.txt b/objstore/CMakeLists.txt index 0cd730b..f258322 100644 --- a/objstore/CMakeLists.txt +++ b/objstore/CMakeLists.txt @@ -117,50 +117,6 @@ target_link_libraries(objstore foonathan::lexy::ext ) -# ============================================================================= -# Plugins -# ============================================================================= -if(PLEXDB_LOG_ENABLED) - add_library(objstore_log_file SHARED) - target_compile_features(objstore_log_file PRIVATE cxx_std_23) - - target_sources(objstore_log_file - PRIVATE - plugins/log_file/log_file_plugin.cpp - ) - - target_include_directories(objstore_log_file - PRIVATE - ${CMAKE_CURRENT_SOURCE_DIR}/../plexdb/log - ) - - add_library(objstore_log_stat SHARED) - target_compile_features(objstore_log_stat PRIVATE cxx_std_20) - - target_sources(objstore_log_stat - PRIVATE - plugins/log_stat/log_stat_plugin.cpp - ) - - target_include_directories(objstore_log_stat - PRIVATE - ${CMAKE_CURRENT_SOURCE_DIR}/../plexdb/log - ) - - add_library(objstore_log_dashboard SHARED) - target_compile_features(objstore_log_dashboard PRIVATE cxx_std_20) - - target_sources(objstore_log_dashboard - PRIVATE - plugins/log_dashboard/log_dashboard_plugin.cpp - ) - - target_include_directories(objstore_log_dashboard - PRIVATE - ${CMAKE_CURRENT_SOURCE_DIR}/../plexdb/log - ) -endif() - # ============================================================================= # Executables # ============================================================================= @@ -196,7 +152,7 @@ if(BUILD_TESTS) FetchContent_Declare( Catch2 GIT_REPOSITORY https://github.com/catchorg/Catch2.git - GIT_TAG v3.11.0 + GIT_TAG v3.13.0 ) FetchContent_MakeAvailable(Catch2) endif() diff --git a/objstore/entry/main.cpp b/objstore/entry/main.cpp index 53c826b..8f2720e 100644 --- a/objstore/entry/main.cpp +++ b/objstore/entry/main.cpp @@ -13,7 +13,7 @@ using namespace objstore; using namespace plexdb; void assert_handler(const char* msg, const char* file_name, const char* function_name, unsigned line_number) { - println("assert failed with message \"", msg, "\""); + println("Assert failed \"", msg, "\" at ", function_name, " in ", file_name, ":", to_str(line_number)); #if PLEXDB_DEBUG PLEXDB_TRAP; diff --git a/objstore/log/log.cpp b/objstore/log/log.cpp index 96be0e1..b3d0b7b 100644 --- a/objstore/log/log.cpp +++ b/objstore/log/log.cpp @@ -4,23 +4,36 @@ import plexdb.base; import plexdb.log; namespace objstore::log { - plexdb::log::Producer producer{"objstore::parser::cql"}; - - void cql_parse_query(plexdb::String8 query) { - plexdb::log::fire_message( - producer.id, - plexdb::log::Level::Debug, - reinterpret_cast(query.data), - query.length - ); + plexdb::log::Producer objstore_parser_cql_producer{"objstore::parser::cql"}; + + void cql_parse_error(const plexdb::String8& error) { + plexdb::log::message(objstore_parser_cql_producer, plexdb::log::Level::Error, error); + } + + plexdb::log::Producer otlp_db_producer{"otlp.db"}; + + void db_query_text(const plexdb::String8& query) { + plexdb::log::message(otlp_db_producer, plexdb::log::Level::Debug, query, "query.text"); + } + + plexdb::log::Stat stat_connection_count{&otlp_db_producer, "client.connection.count", plexdb::log::StatType::Gauge}; + plexdb::log::Stat stat_connection_max{&otlp_db_producer, "client.connection.max", plexdb::log::StatType::Gauge}; + plexdb::log::Stat stat_operation_duration{&otlp_db_producer, "client.operation.duration", plexdb::log::StatType::Gauge}; + plexdb::log::Stat stat_returned_rows{&otlp_db_producer, "client.response.returned_rows", plexdb::log::StatType::Gauge}; + + void db_connection_count(plexdb::S64 active_connections) { + plexdb::log::stat(stat_connection_count, active_connections); + } + + void db_connection_max(plexdb::S64 max_connections) { + plexdb::log::stat(stat_connection_max, max_connections); + } + + void db_operation_duration(plexdb::S64 microseconds) { + plexdb::log::stat(stat_operation_duration, microseconds); } - void cql_parse_error(const char* text, plexdb::U64 len) { - plexdb::log::fire_message( - producer.id, - plexdb::log::Level::Error, - text, - len - ); + void db_response_returned_rows(plexdb::S64 row_count) { + plexdb::log::stat(stat_returned_rows, row_count); } } diff --git a/objstore/log/log.cppm b/objstore/log/log.cppm index 8d12894..a05bf40 100644 --- a/objstore/log/log.cppm +++ b/objstore/log/log.cppm @@ -4,6 +4,12 @@ import plexdb.base; import plexdb.log; export namespace objstore::log { - void cql_parse_query(plexdb::String8 query); - void cql_parse_error(const char* text, plexdb::U64 len); + void db_query_text(const plexdb::String8& query); + void cql_parse_error(const plexdb::String8& error); + + // OTel database metrics (https://opentelemetry.io/docs/specs/semconv/db/database-metrics/) + void db_connection_count(plexdb::S64 active_connections); + void db_connection_max(plexdb::S64 max_connections); + void db_operation_duration(plexdb::S64 microseconds); + void db_response_returned_rows(plexdb::S64 row_count); } diff --git a/objstore/native/native.cppm b/objstore/native/native.cppm index f489139..d534caf 100644 --- a/objstore/native/native.cppm +++ b/objstore/native/native.cppm @@ -13,6 +13,7 @@ import objstore.tcp; import objstore.parsers; import objstore.engine; import objstore.engine.statements; +import objstore.log; using namespace plexdb; using namespace objstore; @@ -479,6 +480,7 @@ namespace objstore::native { } break; case opcode::QUERY: { + S64 t0 = os::monotonic_us(); const U8* p = body; String8 query = read_cql_long_string(p, body_end); // Remaining bytes are query parameters (consistency, flags, etc.) - ignored @@ -487,6 +489,7 @@ namespace objstore::native { if (!cql_opt) { auto frame = make_native_frame(conn, &chunk, write, opcode::ERROR, stream); append_error_body(frame, engine::ExecutionStatus::SyntaxError, "Failed to parse CQL"); + objstore::log::db_operation_duration(os::monotonic_us() - t0); break; } @@ -496,6 +499,7 @@ namespace objstore::native { auto frame = make_native_frame(conn, &chunk, write, opcode::ERROR, stream); String8 msg = result.message.length ? result.message : engine::to_str(result.status); append_error_body(frame, result.status, msg); + objstore::log::db_operation_duration(os::monotonic_us() - t0); break; } @@ -521,13 +525,16 @@ namespace objstore::native { assert_true(tbl != nullptr, "table not found for rows result"); auto frame = make_native_frame(conn, &chunk, write, opcode::RESULT, stream); append_result_rows(frame, result, tbl); + objstore::log::db_response_returned_rows(btree::size(tbl->btree)); }break; case engine::ResultKind::VirtualRows:{ assert_true(result.virtual_rows.has_value(), "virtual rows missing"); auto frame = make_native_frame(conn, &chunk, write, opcode::RESULT, stream); append_result_virtual_rows(frame, *result.virtual_rows); + objstore::log::db_response_returned_rows(result.virtual_rows->rows.length); }break; } + objstore::log::db_operation_duration(os::monotonic_us() - t0); } break; case opcode::REGISTER: { diff --git a/objstore/parsers/parsers.cpp b/objstore/parsers/parsers.cpp index 96ef080..fea59ce 100644 --- a/objstore/parsers/parsers.cpp +++ b/objstore/parsers/parsers.cpp @@ -54,7 +54,7 @@ namespace { error.message()); } - fn(msg.c_str, msg.length); + fn(msg); ++_count; } @@ -69,8 +69,6 @@ namespace { return _sink{0, fn}; } }; - - using LogErrorCallback = ErrorCallback; } namespace objstore::parsers::cql { @@ -1645,23 +1643,8 @@ namespace objstore::parsers::cql { }; } - Optional parse(String8 bytes, bool report_errors) { - log::cql_parse_query(bytes); - - auto input = lexy::string_input(bytes.data, bytes.length); - - auto try_parse = [&](auto callback) -> Optional { - auto result = lexy::parse(input, callback); - if (result.has_value()) return result.value(); - return {}; - }; - - if (report_errors) return try_parse(LogErrorCallback{log::cql_parse_error}); - return try_parse(lexy::noop); - } - - Optional parse(String8 bytes, void(*error_fn)(const char*, size_t)) { - log::cql_parse_query(bytes); + Optional parse(String8 bytes, void(*error_fn)(const String8& error)) { + log::db_query_text(bytes); auto input = lexy::string_input(bytes.data, bytes.length); @@ -1671,6 +1654,6 @@ namespace objstore::parsers::cql { return {}; }; - return try_parse(ErrorCallback{error_fn}); + return try_parse(ErrorCallback{error_fn}); } } diff --git a/objstore/parsers/parsers.cppm b/objstore/parsers/parsers.cppm index 93b9c09..b195fda 100644 --- a/objstore/parsers/parsers.cppm +++ b/objstore/parsers/parsers.cppm @@ -5,6 +5,7 @@ import plexdb.log; import plexdb.tagged_union; import objstore.engine.dtype; import objstore.engine.statements; +import objstore.log; using namespace plexdb; @@ -13,7 +14,6 @@ namespace objstore::parsers { // cassandra query language (CQL) // ======================================================================== namespace cql { - export Optional parse(String8 bytes, bool report_errors=log::enabled); - export Optional parse(String8 bytes, void(*error_fn)(const char*, size_t)); + export Optional parse(String8 bytes, void(*error_fn)(const String8& error) = &log::cql_parse_error); } } diff --git a/objstore/parsers/parsers.test.cpp b/objstore/parsers/parsers.test.cpp index ecaea0f..1618563 100644 --- a/objstore/parsers/parsers.test.cpp +++ b/objstore/parsers/parsers.test.cpp @@ -8,7 +8,6 @@ import plexdb.os.dynamic_tagged_union; import objstore.parsers; import objstore.engine.statements; import objstore.engine.dtype; -import objstore.test.parsers_error_reporter; using namespace plexdb; using namespace objstore; @@ -52,13 +51,13 @@ TEST_CASE("CQL DROP KEYSPACE", "[objstore.cql]") { TEST_CASE("CQL CREATE KEYSPACE statements", "[objstore.parser]") { SECTION("Basic CREATE KEYSPACE") { auto query = "CREATE KEYSPACE my_keyspace WITH replication = 'SimpleStrategy';"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); } } TEST_CASE("CQL CREATE TABLE", "[objstore.cql]") { SECTION("simple table with inline primary key") { - auto result = cql::parse("CREATE TABLE ks.tbl (id int PRIMARY KEY, name text, age int);", catch2_cql_parse_error); + auto result = cql::parse("CREATE TABLE ks.tbl (id int PRIMARY KEY, name text, age int);"); REQUIRE(result.has_value()); auto& stmt = get(result->value); @@ -68,7 +67,7 @@ TEST_CASE("CQL CREATE TABLE", "[objstore.cql]") { SECTION("CREATE KEYSPACE IF NOT EXISTS") { auto query = "CREATE KEYSPACE IF NOT EXISTS test_ks WITH replication = 'NetworkTopologyStrategy';"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); REQUIRE(type_matches_tag(result->value)); @@ -85,7 +84,7 @@ TEST_CASE("CQL CREATE TABLE", "[objstore.cql]") { SECTION("CREATE KEYSPACE with multiple options") { auto query = "CREATE KEYSPACE prod WITH replication = 'SimpleStrategy' AND durable_writes = 'true';"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); REQUIRE(type_matches_tag(result->value)); @@ -105,7 +104,7 @@ TEST_CASE("CQL CREATE TABLE", "[objstore.cql]") { SECTION("CREATE KEYSPACE with three options") { auto query = "CREATE KEYSPACE multi_opt WITH replication = 'NetworkTopologyStrategy' AND durable_writes = 'true' AND strategy_class = 'SimpleStrategy';"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); REQUIRE(type_matches_tag(result->value)); @@ -119,7 +118,7 @@ TEST_CASE("CQL CREATE TABLE", "[objstore.cql]") { SECTION("CREATE KEYSPACE case insensitive") { auto query = "create keyspace TestKS with replication = 'test';"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); REQUIRE(type_matches_tag(result->value)); @@ -130,7 +129,7 @@ TEST_CASE("CQL CREATE TABLE", "[objstore.cql]") { SECTION("CREATE KEYSPACE with underscore in name") { auto query = "CREATE KEYSPACE my_test_keyspace WITH replication = 'SimpleStrategy';"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& ks = get(result->value); @@ -139,7 +138,7 @@ TEST_CASE("CQL CREATE TABLE", "[objstore.cql]") { SECTION("CREATE KEYSPACE with mixed case IF NOT EXISTS") { auto query = "CREATE KEYSPACE If Not Exists mixed_case WITH replication = 'test';"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& ks = get(result->value); @@ -150,7 +149,7 @@ TEST_CASE("CQL CREATE TABLE", "[objstore.cql]") { SECTION("CREATE KEYSPACE with quoted option value") { // @note CQL uses '' to escape single quotes inside strings, not backslash auto query = "CREATE KEYSPACE ks WITH replication = '{''class'': ''SimpleStrategy''}';"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& ks = get(result->value); @@ -161,11 +160,11 @@ TEST_CASE("CQL CREATE TABLE", "[objstore.cql]") { TEST_CASE("CQL CREATE TABLE statements", "[objstore.parser]") { SECTION("Basic CREATE TABLE with single column") { auto query = "CREATE TABLE ks.users (id int PRIMARY KEY);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); } SECTION("if not exists") { - auto result = cql::parse("CREATE TABLE IF NOT EXISTS tbl (id int PRIMARY KEY);", catch2_cql_parse_error); + auto result = cql::parse("CREATE TABLE IF NOT EXISTS tbl (id int PRIMARY KEY);"); REQUIRE(result.has_value()); auto& stmt = get(result->value); REQUIRE(stmt.if_not_exists == true); @@ -189,7 +188,7 @@ TEST_CASE("CQL TRUNCATE", "[objstore.cql]") { TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { SECTION("with column names and values") { - auto result = cql::parse("INSERT INTO tbl (id, name) VALUES (1, 'hello');", catch2_cql_parse_error); + auto result = cql::parse("INSERT INTO tbl (id, name) VALUES (1, 'hello');"); REQUIRE(result.has_value()); auto& stmt = get(result->value); REQUIRE(stmt.table.table_name == "tbl"); @@ -200,7 +199,7 @@ TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { SECTION("CREATE TABLE with multiple columns") { auto query = "CREATE TABLE ks.users (id int PRIMARY KEY, name text, age int);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); REQUIRE(type_matches_tag(result->value)); @@ -224,7 +223,7 @@ TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { SECTION("CREATE TABLE IF NOT EXISTS") { auto query = "CREATE TABLE IF NOT EXISTS ks.products (sku int PRIMARY KEY, name text, price int);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); REQUIRE(type_matches_tag(result->value)); @@ -237,7 +236,7 @@ TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { SECTION("CREATE TABLE with various data types") { auto query = "CREATE TABLE ks.data (id int PRIMARY KEY, name text, count bigint, created timestamp, active boolean);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& tbl = get(result->value); @@ -251,7 +250,7 @@ TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { SECTION("CREATE TABLE with FLOAT and DOUBLE types") { auto query = "CREATE TABLE prod.metrics (id int PRIMARY KEY, temperature float, precision_value double);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& tbl = get(result->value); @@ -262,7 +261,7 @@ TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { SECTION("CREATE TABLE with UUID type") { auto query = "CREATE TABLE ks.sessions (session_id uuid PRIMARY KEY, user_id int);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& tbl = get(result->value); @@ -273,7 +272,7 @@ TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { SECTION("CREATE TABLE case insensitive") { auto query = "create table ks.TestTable (Id INT primary key, Name TEXT);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); REQUIRE(type_matches_tag(result->value)); @@ -284,7 +283,7 @@ TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { SECTION("CREATE TABLE with non-primary key as last column") { auto query = "CREATE TABLE ks.test (id int PRIMARY KEY, data text);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& tbl = get(result->value); @@ -294,7 +293,7 @@ TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { SECTION("CREATE TABLE with primary key in middle") { auto query = "CREATE TABLE ks.test (name text, id int PRIMARY KEY, email text);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& tbl = get(result->value); @@ -306,7 +305,7 @@ TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { SECTION("CREATE TABLE with many columns") { auto query = "CREATE TABLE ks.large (c1 int PRIMARY KEY, c2 text, c3 bigint, c4 timestamp, c5 boolean, c6 float, c7 double);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& tbl = get(result->value); @@ -315,7 +314,7 @@ TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { SECTION("CREATE TABLE with underscore column names") { auto query = "CREATE TABLE ks.test (user_id int PRIMARY KEY, first_name text, last_name text);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& tbl = get(result->value); @@ -328,11 +327,11 @@ TEST_CASE("CQL INSERT INTO", "[objstore.cql]") { TEST_CASE("CQL INSERT INTO statements", "[objstore.parser]") { SECTION("INSERT INTO with integer values") { auto query = "INSERT INTO ks.users VALUES (1, 2, 3);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); } SECTION("if not exists") { - auto result = cql::parse("INSERT INTO tbl (id) VALUES (1) IF NOT EXISTS;", catch2_cql_parse_error); + auto result = cql::parse("INSERT INTO tbl (id) VALUES (1) IF NOT EXISTS;"); REQUIRE(result.has_value()); auto& stmt = get(result->value); REQUIRE(stmt.if_not_exists == true); @@ -341,7 +340,7 @@ TEST_CASE("CQL INSERT INTO statements", "[objstore.parser]") { TEST_CASE("CQL SELECT", "[objstore.cql]") { SECTION("select star") { - auto result = cql::parse("SELECT * FROM tbl;", catch2_cql_parse_error); + auto result = cql::parse("SELECT * FROM tbl;"); REQUIRE(result.has_value()); auto& stmt = get(result->value); REQUIRE(stmt.from.table_name == "tbl"); @@ -361,11 +360,11 @@ TEST_CASE("CQL SELECT", "[objstore.cql]") { SECTION("INSERT INTO with mixed values") { auto query = "INSERT INTO app.users VALUES (123, 'John Doe', 'john@example.com');"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); } SECTION("select with where") { - auto result = cql::parse("SELECT * FROM tbl WHERE id = 1;", catch2_cql_parse_error); + auto result = cql::parse("SELECT * FROM tbl WHERE id = 1;"); REQUIRE(result.has_value()); auto& stmt = get(result->value); } @@ -385,7 +384,7 @@ TEST_CASE("CQL SELECT", "[objstore.cql]") { SECTION("INSERT INTO with negative integers") { // @note negation is represented as UnaryMinusArithmeticOperation, not a folded Constant auto query = "INSERT INTO ks.data VALUES (-100, -50, -1);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& ins = get(result->value); @@ -403,7 +402,7 @@ TEST_CASE("CQL SELECT", "[objstore.cql]") { SECTION("INSERT INTO with large integer") { auto query = "INSERT INTO ks.data VALUES (9223372036854775807);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& ins = get(result->value); @@ -413,7 +412,7 @@ TEST_CASE("CQL SELECT", "[objstore.cql]") { SECTION("INSERT INTO case insensitive") { auto query = "insert into ks.tbl values (1, 'test');"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); REQUIRE(type_matches_tag(result->value)); @@ -421,7 +420,7 @@ TEST_CASE("CQL SELECT", "[objstore.cql]") { SECTION("INSERT INTO with empty string") { auto query = "INSERT INTO ks.tbl VALUES ('');"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& ins = get(result->value); @@ -431,7 +430,7 @@ TEST_CASE("CQL SELECT", "[objstore.cql]") { SECTION("INSERT INTO with string containing spaces") { auto query = "INSERT INTO ks.tbl VALUES ('hello world', 'foo bar baz');"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& ins = get(result->value); @@ -443,7 +442,7 @@ TEST_CASE("CQL SELECT", "[objstore.cql]") { SECTION("INSERT INTO with escaped quotes") { // @note CQL uses '' to escape single quotes inside strings, not backslash auto query = "INSERT INTO ks.tbl VALUES ('''quoted''');"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& ins = get(result->value); @@ -453,7 +452,7 @@ TEST_CASE("CQL SELECT", "[objstore.cql]") { SECTION("INSERT INTO with zero value") { auto query = "INSERT INTO ks.tbl VALUES (0);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& ins = get(result->value); @@ -462,7 +461,7 @@ TEST_CASE("CQL SELECT", "[objstore.cql]") { SECTION("INSERT INTO with multiple string values") { auto query = "INSERT INTO app.messages VALUES ('msg1', 'msg2', 'msg3', 'msg4', 'msg5');"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& ins = get(result->value); @@ -476,7 +475,7 @@ TEST_CASE("CQL SELECT", "[objstore.cql]") { TEST_CASE("CQL SELECT FROM statements", "[objstore.parser]") { SECTION("Basic SELECT FROM") { auto query = "SELECT * FROM ks.users;"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); REQUIRE(type_matches_tag(result->value)); @@ -500,7 +499,7 @@ TEST_CASE("CQL SELECT FROM statements", "[objstore.parser]") { SECTION("SELECT FROM with underscores") { auto query = "SELECT * FROM my_table;"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& sel = get(result->value)); @@ -518,7 +517,7 @@ TEST_CASE("CQL SELECT FROM statements", "[objstore.parser]") { SECTION("SELECT FROM with extra whitespace") { auto query = "SELECT * FROM ks.users ;"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE(result.has_value()); const auto& sel = get(result->value); @@ -540,13 +539,13 @@ TEST_CASE("CQL SELECT FROM statements", "[objstore.parser]") { TEST_CASE("CQL Invalid syntax handling", "[objstore.parser]") { SECTION("Invalid keyword") { auto query = "INVALID STATEMENT;"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } SECTION("Missing table name in CREATE TABLE") { auto query = "CREATE TABLE;"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } @@ -556,66 +555,66 @@ TEST_CASE("CQL Invalid syntax handling", "[objstore.parser]") { SECTION("Missing parentheses in CREATE TABLE") { auto query = "CREATE TABLE ks.users id int PRIMARY KEY;"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } SECTION("Missing WITH in CREATE KEYSPACE") { auto query = "CREATE KEYSPACE ks replication = 'test';"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } SECTION("Empty query") { auto query = ""; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } SECTION("Only whitespace") { auto query = " \n\t "; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } SECTION("Unclosed string in INSERT") { auto query = "INSERT INTO ks.tbl VALUES ('unclosed);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } SECTION("Missing comma between columns") { auto query = "CREATE TABLE ks.test (id int PRIMARY KEY name text);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } SECTION("Missing comma between values") { auto query = "INSERT INTO ks.tbl VALUES (1 2 3);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } SECTION("Invalid data type") { auto query = "CREATE TABLE ks.test (id invalidtype PRIMARY KEY);"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } SECTION("Missing closing parenthesis in INSERT") { auto query = "INSERT INTO ks.tbl VALUES (1, 2, 3;"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } SECTION("Missing closing parenthesis in CREATE TABLE") { auto query = "CREATE TABLE ks.test (id int PRIMARY KEY;"; - auto result = cql::parse(query, catch2_cql_parse_error); + auto result = cql::parse(query); REQUIRE_FALSE(result.has_value()); } SECTION("select json") { - auto result = cql::parse("SELECT JSON * FROM tbl;", catch2_cql_parse_error); + auto result = cql::parse("SELECT JSON * FROM tbl;"); REQUIRE(result.has_value()); auto& stmt = get(result->value)); const auto& stmt = get(result->value)); const auto& stmt = get(result->value)); const auto& stmt = get(result->value)); const auto& stmt = get(result->value)); const auto& stmt = get(result->value)); const auto& stmt = get(result->value); REQUIRE(stmt.order_by->columns.length == 1); @@ -848,7 +847,7 @@ TEST_CASE("Parse SELECT with ORDER BY", "[objstore.parser]") { } SECTION("ORDER BY default ascending") { - auto result = cql::parse("SELECT * FROM ks.users ORDER BY name;", catch2_cql_parse_error); + auto result = cql::parse("SELECT * FROM ks.users ORDER BY name;"); REQUIRE(result.has_value()); const auto& stmt = get(result->value); // @todo @@ -866,7 +865,7 @@ TEST_CASE("Parse SELECT with ORDER BY", "[objstore.parser]") { TEST_CASE("Parse SELECT with ALLOW FILTERING", "[objstore.parser]") { SECTION("Basic ALLOW FILTERING") { - auto result = cql::parse("SELECT * FROM ks.users WHERE age = 25 ALLOW FILTERING;", catch2_cql_parse_error); + auto result = cql::parse("SELECT * FROM ks.users WHERE age = 25 ALLOW FILTERING;"); REQUIRE(result.has_value()); REQUIRE(type_matches_tag(result->value); @@ -874,7 +873,7 @@ TEST_CASE("Parse SELECT with ALLOW FILTERING", "[objstore.parser]") { } SECTION("ALLOW FILTERING with ORDER BY and LIMIT") { - auto result = cql::parse("SELECT * FROM ks.users WHERE age = 25 ORDER BY name LIMIT 100 ALLOW FILTERING;", catch2_cql_parse_error); + auto result = cql::parse("SELECT * FROM ks.users WHERE age = 25 ORDER BY name LIMIT 100 ALLOW FILTERING;"); REQUIRE(result.has_value()); const auto& stmt = get(result->value)); const auto& stmt = get(result->value); // @todo } SECTION("GROUP BY with WHERE and ORDER BY") { - auto result = cql::parse("SELECT * FROM ks.events WHERE user_id = 1 GROUP BY event_type ORDER BY created_at DESC;", catch2_cql_parse_error); + auto result = cql::parse("SELECT * FROM ks.events WHERE user_id = 1 GROUP BY event_type ORDER BY created_at DESC;"); REQUIRE(result.has_value()); const auto& stmt = get(result->value); // @todo @@ -916,7 +915,7 @@ TEST_CASE("Parse SELECT with GROUP BY", "[objstore.parser]") { TEST_CASE("Parse CREATE KEYSPACE with map literal replication", "[objstore.parser]") { SECTION("Simple map replication") { - auto result = cql::parse("CREATE KEYSPACE ks WITH replication = {'class': 'SimpleStrategy'};", catch2_cql_parse_error); + auto result = cql::parse("CREATE KEYSPACE ks WITH replication = {'class': 'SimpleStrategy'};"); REQUIRE(result.has_value()); REQUIRE(type_matches_tag(result->value)); const auto& ks = get(result->value); @@ -928,7 +927,7 @@ TEST_CASE("Parse CREATE KEYSPACE with map literal replication", "[objstore.parse } SECTION("Map with multiple entries") { - auto result = cql::parse("CREATE KEYSPACE ks WITH replication = {'class': 'SimpleStrategy', 'replication_factor': 3};", catch2_cql_parse_error); + auto result = cql::parse("CREATE KEYSPACE ks WITH replication = {'class': 'SimpleStrategy', 'replication_factor': 3};"); REQUIRE(result.has_value()); const auto& ks = get(result->value); const auto& map = get(ks.options.identifier_values[0].second); @@ -936,7 +935,7 @@ TEST_CASE("Parse CREATE KEYSPACE with map literal replication", "[objstore.parse } SECTION("NetworkTopologyStrategy with datacenter configs") { - auto result = cql::parse("CREATE KEYSPACE ks WITH replication = {'class': 'NetworkTopologyStrategy', 'dc1': 3, 'dc2': 2};", catch2_cql_parse_error); + auto result = cql::parse("CREATE KEYSPACE ks WITH replication = {'class': 'NetworkTopologyStrategy', 'dc1': 3, 'dc2': 2};"); REQUIRE(result.has_value()); const auto& ks = get(result->value); const auto& map = get(ks.options.identifier_values[0].second); @@ -944,7 +943,7 @@ TEST_CASE("Parse CREATE KEYSPACE with map literal replication", "[objstore.parse } SECTION("Mix of map and scalar options") { - auto result = cql::parse("CREATE KEYSPACE ks WITH replication = {'class': 'SimpleStrategy'} AND durable_writes = 'true';", catch2_cql_parse_error); + auto result = cql::parse("CREATE KEYSPACE ks WITH replication = {'class': 'SimpleStrategy'} AND durable_writes = 'true';"); REQUIRE(result.has_value()); const auto& ks = get(result->value); REQUIRE(ks.options.identifier_values.length == 2); @@ -957,40 +956,40 @@ TEST_CASE("Parse CREATE KEYSPACE with map literal replication", "[objstore.parse TEST_CASE("CQL parse error reporting", "[objstore.parser]") { SECTION("Invalid syntax returns empty with Catch2 reporter") { - auto result = cql::parse("INVALID STATEMENT;", catch2_cql_parse_error); + auto result = cql::parse("INVALID STATEMENT;"); REQUIRE_FALSE(result.has_value()); } SECTION("Valid query succeeds with Catch2 reporter") { - auto result = cql::parse("SELECT * FROM ks.tbl;", catch2_cql_parse_error); + auto result = cql::parse("SELECT * FROM ks.tbl;"); REQUIRE(result.has_value()); } SECTION("Empty query returns empty with Catch2 reporter") { - auto result = cql::parse("", catch2_cql_parse_error); + auto result = cql::parse(""); REQUIRE_FALSE(result.has_value()); } SECTION("Unclosed string returns empty with Catch2 reporter") { - auto result = cql::parse("INSERT INTO ks.tbl VALUES ('unclosed);", catch2_cql_parse_error); + auto result = cql::parse("INSERT INTO ks.tbl VALUES ('unclosed);"); REQUIRE_FALSE(result.has_value()); } SECTION("Invalid syntax returns empty with bool reporter") { - auto result = cql::parse("CREATE TABLE;", true); + auto result = cql::parse("CREATE TABLE;"); REQUIRE_FALSE(result.has_value()); } } TEST_CASE("CQL quoted identifiers", "[objstore.cql]") { - auto result = cql::parse("SELECT * FROM \"MyTable\";", catch2_cql_parse_error); + auto result = cql::parse("SELECT * FROM \"MyTable\";"); REQUIRE(result.has_value()); auto& stmt = get