From b5450af8f993f9c874adbe17b7c167dccb1a2efa Mon Sep 17 00:00:00 2001 From: Alan George Date: Fri, 15 May 2026 11:42:49 -0600 Subject: [PATCH 01/18] Forward FFI log events to LK log --- src/ffi_client.cpp | 29 ++++++++ src/lk_log.h | 11 +++ src/logging.cpp | 21 ++++++ src/tests/unit/test_logging.cpp | 120 ++++++++++++++++++++++++++++++++ 4 files changed, 181 insertions(+) diff --git a/src/ffi_client.cpp b/src/ffi_client.cpp index d0b2af55..9b7ddf4e 100644 --- a/src/ffi_client.cpp +++ b/src/ffi_client.cpp @@ -207,7 +207,36 @@ proto::FfiResponse FfiClient::sendRequest(const proto::FfiRequest& request) cons return response; } +LogLevel fromProtoLogLevel(proto::LogLevel level) { + switch (level) { + case proto::LOG_ERROR: + return LogLevel::Error; + case proto::LOG_WARN: + return LogLevel::Warn; + case proto::LOG_INFO: + return LogLevel::Info; + case proto::LOG_DEBUG: + return LogLevel::Debug; + case proto::LOG_TRACE: + return LogLevel::Trace; + default: + return LogLevel::Info; + } +} + +void forwardFfiLogBatch(const proto::LogBatch& batch) { + for (int i = 0; i < batch.records_size(); ++i) { + const auto& rec = batch.records(i); + detail::forwardFfiLog(fromProtoLogLevel(rec.level()), rec.target(), rec.message()); + } +} + void FfiClient::PushEvent(const proto::FfiEvent& event) const { + // Forward any FFI logs to the SDK logger + if (event.has_logs()) { + forwardFfiLogBatch(event.logs()); + } + std::unique_ptr to_complete; std::vector listeners_copy; { diff --git a/src/lk_log.h b/src/lk_log.h index e2aa5f15..3c361ac7 100644 --- a/src/lk_log.h +++ b/src/lk_log.h @@ -19,7 +19,9 @@ #include #include +#include +#include "livekit/logging.h" #include "livekit/visibility.h" namespace livekit::detail { @@ -32,6 +34,15 @@ LIVEKIT_INTERNAL_API std::shared_ptr getLogger(); /// Tears down the spdlog logger. Called by livekit::shutdown(). LIVEKIT_INTERNAL_API void shutdownLogger(); +/// Forward a single record received from the Rust FFI log bridge into the +/// SDK's spdlog sinks. The supplied @p target is preserved as the +/// `logger_name` exposed to any user-installed `setLogCallback`, allowing +/// callers to distinguish between e.g. "livekit", "libwebrtc", +/// "tokio-tungstenite", etc. +/// +/// Filtering uses the same level set via `livekit::setLogLevel`. +LIVEKIT_INTERNAL_API void forwardFfiLog(LogLevel level, const std::string& target, const std::string& message); + } // namespace livekit::detail // Convenience macros — two-tier filtering: diff --git a/src/logging.cpp b/src/logging.cpp index 2e66e3a5..7802f1f8 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -111,6 +111,27 @@ void shutdownLogger() { } } +void forwardFfiLog(LogLevel level, const std::string& target, const std::string& message) { + // Snapshot the current logger via shared_ptr so that a concurrent + // setLogCallback() / shutdownLogger() cannot race with our sink iteration. + auto logger = getLogger(); + const auto spd_level = toSpdlogLevel(level); + if (!logger->should_log(spd_level)) { + return; + } + + // Construct a log_msg directly so the Rust target survives as + // `logger_name`, instead of being collapsed into the single "livekit" + // logger name that spdlog would otherwise apply. + const spdlog::details::log_msg msg(spdlog::source_loc{}, spdlog::string_view_t{target.data(), target.size()}, + spd_level, spdlog::string_view_t{message.data(), message.size()}); + for (auto& sink : logger->sinks()) { + if (sink->should_log(spd_level)) { + sink->log(msg); + } + } +} + } // namespace detail void setLogLevel(LogLevel level) { detail::getLogger()->set_level(toSpdlogLevel(level)); } diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index a58dbff5..f13cbb41 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -18,6 +18,8 @@ #include #include +#include +#include #include #include #include @@ -240,6 +242,124 @@ TEST_F(LoggingTest, ConcurrentSetLogLevelDoesNotCrash) { } } +// --------------------------------------------------------------------------- +// Rust FFI -> C++ log forwarding +// --------------------------------------------------------------------------- + +namespace { + +const char* logLevelName(LogLevel level) { + switch (level) { + case LogLevel::Trace: + return "TRACE"; + case LogLevel::Debug: + return "DEBUG"; + case LogLevel::Info: + return "INFO"; + case LogLevel::Warn: + return "WARN"; + case LogLevel::Error: + return "ERROR"; + case LogLevel::Critical: + return "CRITICAL"; + case LogLevel::Off: + return "OFF"; + } + return "?"; +} + +} // namespace + +// Verifies that records emitted from the Rust FFI core surface through the +// user-installed `setLogCallback` when the SDK is initialised with +// `LogSink::kCallback`. Without this wiring, log forwarding would silently +// drop on the C++ side even though Rust is shipping `LogBatch` events over +// the FFI bridge. +// +// This test does NOT use the `LoggingTest` fixture because that fixture +// pre-initialises the SDK with `LogSink::kConsole` (i.e. `capture_logs=false` +// on the Rust side). Toggling capture_logs requires a fresh +// `livekit::initialize()` call, so we manage the SDK lifecycle inline. +TEST(FfiLoggingTest, RustLogsReachUserCallback) { + // Defensive: ensure the SDK is in a clean state in case this test runs + // after another test that left it initialised. shutdown() is a no-op + // when not initialised. + livekit::shutdown(); + + struct Captured { + LogLevel level; + std::string logger_name; + std::string message; + }; + + std::mutex mtx; + std::vector captured; + + // Install the callback BEFORE initialize() so that the very first records + // emitted by Rust during FFI server setup (e.g. "initializing ffi server + // v...") are observed. Each record is also echoed to std::cout for ad + // hoc inspection of what the Rust side is forwarding. + livekit::setLogCallback([&](LogLevel level, const std::string& logger_name, const std::string& message) { + const std::scoped_lock lock(mtx); + std::cout << "[ffi-log] [" << logLevelName(level) << "] [" << logger_name << "] " << message << std::endl; + captured.push_back({level, logger_name, message}); + }); + livekit::setLogLevel(LogLevel::Trace); + + ASSERT_TRUE(livekit::initialize(LogLevel::Trace, LogSink::kCallback)); + + // The Rust FFI logger batches records and flushes on the next iteration + // of its forwarding task. Poll up to 5s for the well-known startup log + // to surface; this is generous to keep CI stable but typically resolves + // in well under a second. + const auto deadline = std::chrono::steady_clock::now() + std::chrono::seconds(5); + bool found_rust_log = false; + while (std::chrono::steady_clock::now() < deadline) { + { + const std::scoped_lock lock(mtx); + for (const auto& entry : captured) { + if (entry.message.find("initializing ffi server") != std::string::npos) { + found_rust_log = true; + break; + } + } + } + if (found_rust_log) { + break; + } + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + } + + EXPECT_TRUE(found_rust_log) << "Expected the Rust 'initializing ffi server' log record to reach the C++ " + "setLogCallback via the FFI LogBatch bridge"; + + // Sanity-check that the forwarded record carries the Rust target as the + // logger name (i.e. NOT the C++-side "livekit" logger), proving that the + // bridge preserves provenance instead of collapsing every record into the + // SDK logger. + bool saw_non_livekit_logger = false; + { + const std::scoped_lock lock(mtx); + for (const auto& entry : captured) { + if (entry.message.find("initializing ffi server") != std::string::npos) { + // Rust's `log::info!` in `livekit-ffi` reports a target rooted at + // `livekit_ffi::...`; we only require that *some* target was + // surfaced (any non-empty string), since the exact target string + // is owned by the Rust side and may evolve. + EXPECT_FALSE(entry.logger_name.empty()) << "FFI-forwarded log record should carry a target name"; + } + if (!entry.logger_name.empty() && entry.logger_name != "livekit") { + saw_non_livekit_logger = true; + } + } + } + EXPECT_TRUE(saw_non_livekit_logger) + << "Expected at least one forwarded record to carry a Rust-side target distinct from the C++ 'livekit' logger"; + + livekit::setLogCallback(nullptr); + livekit::shutdown(); +} + TEST_F(LoggingTest, ConcurrentLogEmissionDoesNotCrash) { std::atomic call_count{0}; From 55183f0fbb554f12655acade337d047c83c31b30 Mon Sep 17 00:00:00 2001 From: Alan George Date: Fri, 15 May 2026 18:17:18 -0600 Subject: [PATCH 02/18] Get rust logs through actually --- AGENTS.md | 49 +++++++++- src/livekit.cpp | 2 +- src/tests/unit/test_logging.cpp | 153 +++++++++++++++++++++++++++++++- 3 files changed, 199 insertions(+), 5 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 366d95af..546de477 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -230,11 +230,54 @@ with the same library loaded elsewhere in the host process. Code should be easy to read and understand. If a sacrifice is made for performance or readability, it should be documented. -Adhere to clang-format checks configured in `.clang-format`. Run `./scripts/clang-format.sh` if needed to confirm code styling, and `./scripts/clang-format.sh --fix` to auto-format generated code created. +#### Formatting (clang-format) -### Static Analysis +The repo enforces `.clang-format` in CI (see `.github/workflows/builds.yml` → +`clang-format` job). Any divergence fails the build. -Adhere to clang-tidy checks configured in `.clang-tidy`. Run `./scripts/clang-tidy.sh` if needed to confirm code quality. +**Required workflow when generating or editing C/C++ code:** + +1. After completing a set of edits to any `.c`, `.cc`, `.cpp`, `.cxx`, `.h`, + `.hpp`, or `.hxx` file under `src/`, `include/`, or `benchmarks/`, run: + + ```bash + ./scripts/clang-format.sh --fix + ``` + + Pass the explicit paths so the run is fast; omit them only when doing a + sweep over the entire tree. +2. If clang-format reports any rewrites, treat the rewritten contents as the + final state and re-read the file before doing any further edits to it. +3. Do not commit, hand off, or declare a task complete with un-formatted + code. CI will reject it and the round-trip wastes time. + +`./scripts/clang-format.sh` (no `--fix`) runs in dry-run / `--Werror` mode and +is what CI uses; it exits non-zero on any divergence. + +#### Static Analysis (clang-tidy) + +The repo enforces `.clang-tidy` in CI (see `.github/workflows/builds.yml` → +`clang-tidy` job, run with `--fail-on-warning`). Any new warning fails the +build. + +**Required workflow when generating or editing C/C++ code:** + +1. After substantive C/C++ edits — especially anything that adds new + identifiers, new enums, new public API, new free functions, or that + touches the FFI / threading boundary — run: + + ```bash + ./scripts/clang-tidy.sh + ``` + + This requires a prior `./build.sh release` (or + `./build.sh release-tests` / `release-all`) so that + `build-release/compile_commands.json` and the generated protobuf headers + exist. +2. Address any new findings introduced by your edits. Do not introduce new + `// NOLINT` suppressions without a one-line comment explaining *why*. +3. Pre-existing findings in code you did not touch are out of scope unless + the user explicitly asks for a sweep. ## Dependencies diff --git a/src/livekit.cpp b/src/livekit.cpp index 1bcd9df9..a2b555ec 100644 --- a/src/livekit.cpp +++ b/src/livekit.cpp @@ -24,7 +24,7 @@ namespace livekit { bool initialize(const LogLevel& level, const LogSink& log_sink) { setLogLevel(level); auto& ffi_client = FfiClient::instance(); - return ffi_client.initialize(log_sink == LogSink::kCallback); + return ffi_client.initialize(true); } void shutdown() { diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index f13cbb41..ba83e39b 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -15,11 +15,14 @@ */ #include +#include #include +#include #include #include #include +#include #include #include #include @@ -301,7 +304,7 @@ TEST(FfiLoggingTest, RustLogsReachUserCallback) { // hoc inspection of what the Rust side is forwarding. livekit::setLogCallback([&](LogLevel level, const std::string& logger_name, const std::string& message) { const std::scoped_lock lock(mtx); - std::cout << "[ffi-log] [" << logLevelName(level) << "] [" << logger_name << "] " << message << std::endl; + std::cout << "[ffi-log] [" << logLevelName(level) << "] [" << logger_name << "] " << message << '\n'; captured.push_back({level, logger_name, message}); }); livekit::setLogLevel(LogLevel::Trace); @@ -360,6 +363,154 @@ TEST(FfiLoggingTest, RustLogsReachUserCallback) { livekit::shutdown(); } +TEST_F(LoggingTest, DummyRustTest) { + livekit::shutdown(); + ASSERT_TRUE(livekit::initialize(LogLevel::Info)); + LK_LOG_INFO("Hello from C++ SDK"); + + // The single FFI call here -- CreateAudioTrack -- is what crosses the FFI + // boundary into the `livekit` crate and triggers `LkRuntime::instance()`. + // The AudioSource ctor on its own does NOT instantiate LkRuntime; the + // track creation does. + { + auto audio_source = std::make_shared(48000, 1); + auto track = LocalAudioTrack::createLocalAudioTrack("ffi-log-probe", audio_source); + ASSERT_NE(track, nullptr); + // Hold the handles briefly so any synchronous Rust-side debug logs land + // before the strong refs drop. The FFI logger flushes on a 1s interval, + // so this sleep does not gate observability -- it just keeps things tidy. + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + } +} + +// Verifies that internal Rust logs originating BELOW the FFI layer (i.e. in +// the `livekit` crate or in libwebrtc itself, not in `livekit-ffi`) propagate +// through the FFI bridge into the user-installed `setLogCallback`. +// +// The sibling `RustLogsReachUserCallback` test only proves that the FFI layer +// itself can forward its own startup log (`"initializing ffi server"`, +// emitted from inside `livekit_ffi::server::FfiServer::setup`). That alone +// does not prove that records emitted by deeper Rust crates -- which is what +// shows up under `RUST_LOG=debug` as `[DEBUG libwebrtc] (...)` or as logs +// targeted at `livekit::rtc_engine::*` -- also reach the user callback. +// +// Trigger path used here (fully in-process, no network): +// +// C++ LocalAudioTrack::createLocalAudioTrack +// -> FFI request CreateAudioTrack +// -> Rust on_create_audio_track (livekit_ffi crate) +// -> LocalAudioTrack::create_audio_track (livekit crate) +// -> LkRuntime::instance() +// -> log::debug!("LkRuntime::new()") +// target = "livekit::rtc_engine::lk_runtime" +// -> PeerConnectionFactory::default() (libwebrtc-rs) +// -> installs the libwebrtc LogSink that forwards every +// internal libwebrtc message as `log::debug!(target: +// "libwebrtc", ...)`. +// +// The libwebrtc-internal logs (e.g. the `text_pcap_packet_observer.cc` lines +// the user sees under `RUST_LOG=debug`) generally fire only during real +// signaling / ICE / SDP work, which requires a live LiveKit server and so +// belong in integration tests. The deepest deterministic signal we can +// trigger from a unit test is `LkRuntime::new()` -- which is still below the +// FFI layer (it lives in the `livekit` Rust crate), so capturing it proves +// the cross-crate forwarding works. +// +// Note about std::cout: the test installs a `setLogCallback`, which causes +// the C++ logging layer to swap its spdlog sink set entirely for a callback +// sink. While the callback is installed, no SDK log output reaches stderr or +// stdout, so this test does NOT pollute GTest's console output (the only +// echoes are the deliberate ad-hoc `[ffi-log]` prints below). +TEST(FfiLoggingTest, LogsFromBelowFfiLayerReachUserCallback) { + // Defensive: start from a clean slate in case another test left the SDK + // initialised. shutdown() is a no-op when not initialised. + livekit::shutdown(); + + struct Captured { + LogLevel level; + std::string logger_name; + std::string message; + }; + + std::mutex mtx; + std::vector captured; + + // Install BEFORE initialize() so any startup records are observed too. + // livekit::setLogCallback([&](LogLevel level, const std::string& logger_name, const std::string& message) { + // const std::scoped_lock lock(mtx); + // std::cout << "[ffi-log] [" << logLevelName(level) << "] [" << logger_name << "] " << message << '\n'; + // captured.push_back({level, logger_name, message}); + // }); + + // Trace level so the FFI logger forwards everything + ASSERT_TRUE(livekit::initialize(LogLevel::Trace, LogSink::kCallback)); + + // The single FFI call here -- CreateAudioTrack -- is what crosses the FFI + // boundary into the `livekit` crate and triggers `LkRuntime::instance()`. + // The AudioSource ctor on its own does NOT instantiate LkRuntime; the + // track creation does. + { + auto audio_source = std::make_shared(48000, 1); + auto track = LocalAudioTrack::createLocalAudioTrack("ffi-log-probe", audio_source); + ASSERT_NE(track, nullptr); + // Hold the handles briefly so any synchronous Rust-side debug logs land + // before the strong refs drop. The FFI logger flushes on a 1s interval, + // so this sleep does not gate observability -- it just keeps things tidy. + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + } + + // The Rust FfiLogger batches log records and flushes on a 1-second tick + // (see livekit-ffi/src/server/logger.rs FLUSH_INTERVAL). Allow generous + // headroom for slow CI machines without making the test wall-time-heavy. + const auto deadline = std::chrono::steady_clock::now() + std::chrono::seconds(5); + bool found_below_ffi_log = false; + std::string matched_target; + std::string matched_message; + while (std::chrono::steady_clock::now() < deadline) { + { + const std::scoped_lock lock(mtx); + for (const auto& entry : captured) { + // Targets demonstrably emitted from a layer BELOW livekit-ffi: + // * "livekit::..." -> livekit Rust crate (e.g. LkRuntime) + // * "libwebrtc" -> libwebrtc-rs LogSink shim + // * "webrtc"/"webrtc::..." -> direct libwebrtc-rs targets, future-proofing + // We deliberately do NOT match "livekit_ffi" here -- that's the FFI + // layer itself and would not prove cross-crate propagation. + const auto& t = entry.logger_name; + const bool is_livekit_crate = t.rfind("livekit::", 0) == 0; + const bool is_libwebrtc = (t == "libwebrtc"); + const bool is_webrtc_crate = (t == "webrtc") || t.rfind("webrtc::", 0) == 0; + if (is_livekit_crate || is_libwebrtc || is_webrtc_crate) { + found_below_ffi_log = true; + matched_target = t; + matched_message = entry.message; + break; + } + } + } + if (found_below_ffi_log) { + break; + } + std::this_thread::sleep_for(std::chrono::milliseconds(50)); + } + + EXPECT_TRUE(found_below_ffi_log) << "Expected at least one log record from below the FFI layer " + "(target starting with 'livekit::', 'libwebrtc', or 'webrtc') to " + "reach the C++ setLogCallback. This validates the " + "C++ -> FFI -> livekit-rust -> log -> FFI -> C++ chain. If this " + "fires, it likely means either capture_logs=true is not being " + "honoured by the Rust FfiLogger, or the LkRuntime weak-ref is " + "still upgrading from a previous test (in which case run this " + "test in isolation: --gtest_filter=FfiLoggingTest.LogsFromBelowFfiLayer*)."; + + if (found_below_ffi_log) { + // Ad hoc breadcrumb so test logs make it obvious WHICH below-FFI record + // was the one that satisfied the assertion. + std::cout << "[ffi-log] matched below-FFI target='" << matched_target << "' message='" << matched_message << "'" + << '\n'; + } +} + TEST_F(LoggingTest, ConcurrentLogEmissionDoesNotCrash) { std::atomic call_count{0}; From 8b841ee559ffba9a2963b771519330ad1b3bf43b Mon Sep 17 00:00:00 2001 From: Alan George Date: Mon, 18 May 2026 11:51:44 -0700 Subject: [PATCH 03/18] Cleaned up event callback for Ffi, added panic support, cleaner unit test for Rust log forwarding --- src/ffi_client.cpp | 33 +-- src/ffi_client.h | 2 +- src/tests/CMakeLists.txt | 1 + src/tests/unit/test_logging.cpp | 342 +++++++++++--------------------- 4 files changed, 132 insertions(+), 246 deletions(-) diff --git a/src/ffi_client.cpp b/src/ffi_client.cpp index 9b7ddf4e..d70450be 100644 --- a/src/ffi_client.cpp +++ b/src/ffi_client.cpp @@ -17,6 +17,7 @@ #include "ffi_client.h" #include +#include #include "data_track.pb.h" #include "e2ee.pb.h" @@ -207,7 +208,7 @@ proto::FfiResponse FfiClient::sendRequest(const proto::FfiRequest& request) cons return response; } -LogLevel fromProtoLogLevel(proto::LogLevel level) { +LogLevel toSpdlogLevel(proto::LogLevel level) { switch (level) { case proto::LOG_ERROR: return LogLevel::Error; @@ -224,19 +225,7 @@ LogLevel fromProtoLogLevel(proto::LogLevel level) { } } -void forwardFfiLogBatch(const proto::LogBatch& batch) { - for (int i = 0; i < batch.records_size(); ++i) { - const auto& rec = batch.records(i); - detail::forwardFfiLog(fromProtoLogLevel(rec.level()), rec.target(), rec.message()); - } -} - void FfiClient::PushEvent(const proto::FfiEvent& event) const { - // Forward any FFI logs to the SDK logger - if (event.has_logs()) { - forwardFfiLogBatch(event.logs()); - } - std::unique_ptr to_complete; std::vector listeners_copy; { @@ -268,11 +257,27 @@ void FfiClient::PushEvent(const proto::FfiEvent& event) const { } } -void LivekitFfiCallback(const uint8_t* buf, size_t len) { +LIVEKIT_INTERNAL_API void LivekitFfiCallback(const uint8_t* buf, size_t len) { proto::FfiEvent event; event.ParseFromArray(buf, static_cast(len)); // TODO: this fixes for now, what if len exceeds int? + // Forward any FFI logs to the SDK logger + if (event.has_logs()) { + for (const auto& rec : event.logs().records()) { + detail::forwardFfiLog(toSpdlogLevel(rec.level()), rec.target(), rec.message()); + } + return; // No need to queue the logs + } + + // We are in a unrecoverable state, terminate the process + // This is what Python does, may not make sense for C++ + if (event.has_panic()) { + std::cerr << "FFI Panic: " << event.panic().message() << '\n'; + std::raise(SIGTERM); + return; + } + FfiClient::instance().PushEvent(event); } diff --git a/src/ffi_client.h b/src/ffi_client.h index dc00d565..387336df 100644 --- a/src/ffi_client.h +++ b/src/ffi_client.h @@ -58,7 +58,7 @@ extern "C" void livekit_ffi_initialize(FfiCallbackFn cb, bool capture_logs, cons extern "C" void livekit_ffi_dispose(); -extern "C" void LivekitFfiCallback(const uint8_t* buf, size_t len); +LIVEKIT_INTERNAL_API extern "C" void LivekitFfiCallback(const uint8_t* buf, size_t len); // The FfiClient is used to communicate with the FFI interface of the Rust SDK // We use the generated protocol messages to facilitate the communication. diff --git a/src/tests/CMakeLists.txt b/src/tests/CMakeLists.txt index 2bd0c09e..ca40bec7 100644 --- a/src/tests/CMakeLists.txt +++ b/src/tests/CMakeLists.txt @@ -62,6 +62,7 @@ if(UNIT_TEST_SOURCES) target_link_libraries(livekit_unit_tests PRIVATE livekit + livekit_ffi spdlog::spdlog ${LIVEKIT_PROTOBUF_TARGET} GTest::gtest_main diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index ba83e39b..b1d99db9 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -21,6 +21,7 @@ #include #include +#include #include #include #include @@ -28,10 +29,20 @@ #include #include +#include "ffi_client.h" +#include "livekit_ffi.h" #include "lk_log.h" namespace livekit::test { +namespace { + +// FFI event entry point for tests. Forwards to the SDK handler so log batches +// reach setLogCallback() the same way they do in production. +extern "C" void testFfiCallback(const uint8_t* buf, size_t len) { LivekitFfiCallback(buf, len); } + +} // namespace + class LoggingTest : public ::testing::Test { protected: void SetUp() override { livekit::initialize(); } @@ -245,12 +256,41 @@ TEST_F(LoggingTest, ConcurrentSetLogLevelDoesNotCrash) { } } +TEST_F(LoggingTest, ConcurrentLogEmissionDoesNotCrash) { + std::atomic call_count{0}; + + livekit::setLogCallback([&](LogLevel, const std::string&, const std::string&) { call_count.fetch_add(1); }); + + livekit::setLogLevel(LogLevel::Trace); + + constexpr int kThreads = 8; + constexpr int kIterations = 200; + + std::vector threads; + threads.reserve(kThreads); + + for (int t = 0; t < kThreads; ++t) { + threads.emplace_back([&, t]() { + for (int i = 0; i < kIterations; ++i) { + LK_LOG_INFO("thread {} iteration {}", t, i); + } + }); + } + + for (auto& th : threads) { + th.join(); + } + + EXPECT_GE(call_count.load(), kThreads * kIterations); +} + // --------------------------------------------------------------------------- // Rust FFI -> C++ log forwarding // --------------------------------------------------------------------------- namespace { +// Utility function to convert LogLevel to a string for debug printing const char* logLevelName(LogLevel level) { switch (level) { case LogLevel::Trace: @@ -273,181 +313,100 @@ const char* logLevelName(LogLevel level) { } // namespace -// Verifies that records emitted from the Rust FFI core surface through the -// user-installed `setLogCallback` when the SDK is initialised with -// `LogSink::kCallback`. Without this wiring, log forwarding would silently -// drop on the C++ side even though Rust is shipping `LogBatch` events over -// the FFI bridge. -// -// This test does NOT use the `LoggingTest` fixture because that fixture -// pre-initialises the SDK with `LogSink::kConsole` (i.e. `capture_logs=false` -// on the Rust side). Toggling capture_logs requires a fresh -// `livekit::initialize()` call, so we manage the SDK lifecycle inline. -TEST(FfiLoggingTest, RustLogsReachUserCallback) { - // Defensive: ensure the SDK is in a clean state in case this test runs - // after another test that left it initialised. shutdown() is a no-op - // when not initialised. - livekit::shutdown(); +// Used by multiple tests +struct Captured { + LogLevel level; + std::string logger_name; + std::string message; +}; - struct Captured { - LogLevel level; - std::string logger_name; - std::string message; - }; +TEST_F(LoggingTest, RustLogsAreForwarded) { + // User toggle for debugging this unit test + bool print_logs = true; - std::mutex mtx; + // Start from clean slate + livekit::shutdown(); + std::mutex mut; + std::condition_variable cv; std::vector captured; + bool decode_error_received = false; - // Install the callback BEFORE initialize() so that the very first records - // emitted by Rust during FFI server setup (e.g. "initializing ffi server - // v...") are observed. Each record is also echoed to std::cout for ad - // hoc inspection of what the Rust side is forwarding. + livekit::setLogLevel(LogLevel::Trace); livekit::setLogCallback([&](LogLevel level, const std::string& logger_name, const std::string& message) { - const std::scoped_lock lock(mtx); - std::cout << "[ffi-log] [" << logLevelName(level) << "] [" << logger_name << "] " << message << '\n'; + const std::scoped_lock lock(mut); captured.push_back({level, logger_name, message}); - }); - livekit::setLogLevel(LogLevel::Trace); - - ASSERT_TRUE(livekit::initialize(LogLevel::Trace, LogSink::kCallback)); - - // The Rust FFI logger batches records and flushes on the next iteration - // of its forwarding task. Poll up to 5s for the well-known startup log - // to surface; this is generous to keep CI stable but typically resolves - // in well under a second. - const auto deadline = std::chrono::steady_clock::now() + std::chrono::seconds(5); - bool found_rust_log = false; - while (std::chrono::steady_clock::now() < deadline) { - { - const std::scoped_lock lock(mtx); - for (const auto& entry : captured) { - if (entry.message.find("initializing ffi server") != std::string::npos) { - found_rust_log = true; - break; - } - } + if (print_logs) { + std::cout << "[Captured Rust log] [" << logLevelName(level) << "] [" << logger_name << "] " << message << '\n'; } - if (found_rust_log) { - break; + + // Check for specific known error message for condition variable wait. Otherwise we have to sleep a second + // for the 1Hz flush interval, which slows this test down unnecessarily + if (level == LogLevel::Error && message.find("failed to decode request") != std::string::npos) { + decode_error_received = true; + cv.notify_one(); } - std::this_thread::sleep_for(std::chrono::milliseconds(50)); - } + }); - EXPECT_TRUE(found_rust_log) << "Expected the Rust 'initializing ffi server' log record to reach the C++ " - "setLogCallback via the FFI LogBatch bridge"; + ASSERT_NO_THROW(livekit_ffi_initialize(testFfiCallback, true, "cpp-test", "1.0.0")); - // Sanity-check that the forwarded record carries the Rust target as the - // logger name (i.e. NOT the C++-side "livekit" logger), proving that the - // bridge preserves provenance instead of collapsing every record into the - // SDK logger. - bool saw_non_livekit_logger = false; + // Induce a Rust-side error log via an invalid protobuf payload { - const std::scoped_lock lock(mtx); - for (const auto& entry : captured) { - if (entry.message.find("initializing ffi server") != std::string::npos) { - // Rust's `log::info!` in `livekit-ffi` reports a target rooted at - // `livekit_ffi::...`; we only require that *some* target was - // surfaced (any non-empty string), since the exact target string - // is owned by the Rust side and may evolve. - EXPECT_FALSE(entry.logger_name.empty()) << "FFI-forwarded log record should carry a target name"; - } - if (!entry.logger_name.empty() && entry.logger_name != "livekit") { - saw_non_livekit_logger = true; - } - } + std::vector data(100); + const uint8_t* res_ptr = nullptr; + size_t res_len = 0; + const auto handle = livekit_ffi_request(data.data(), data.size(), &res_ptr, &res_len); + EXPECT_EQ(handle, INVALID_HANDLE); } - EXPECT_TRUE(saw_non_livekit_logger) - << "Expected at least one forwarded record to carry a Rust-side target distinct from the C++ 'livekit' logger"; - - livekit::setLogCallback(nullptr); - livekit::shutdown(); -} -TEST_F(LoggingTest, DummyRustTest) { - livekit::shutdown(); - ASSERT_TRUE(livekit::initialize(LogLevel::Info)); - LK_LOG_INFO("Hello from C++ SDK"); - - // The single FFI call here -- CreateAudioTrack -- is what crosses the FFI - // boundary into the `livekit` crate and triggers `LkRuntime::instance()`. - // The AudioSource ctor on its own does NOT instantiate LkRuntime; the - // track creation does. + // Wait for the error log to be captured { - auto audio_source = std::make_shared(48000, 1); - auto track = LocalAudioTrack::createLocalAudioTrack("ffi-log-probe", audio_source); - ASSERT_NE(track, nullptr); - // Hold the handles briefly so any synchronous Rust-side debug logs land - // before the strong refs drop. The FFI logger flushes on a 1s interval, - // so this sleep does not gate observability -- it just keeps things tidy. - std::this_thread::sleep_for(std::chrono::milliseconds(50)); + std::unique_lock lock(mut); + ASSERT_TRUE(cv.wait_for(lock, std::chrono::seconds(1), [&] { return decode_error_received; })); } -} -// Verifies that internal Rust logs originating BELOW the FFI layer (i.e. in -// the `livekit` crate or in libwebrtc itself, not in `livekit-ffi`) propagate -// through the FFI bridge into the user-installed `setLogCallback`. -// -// The sibling `RustLogsReachUserCallback` test only proves that the FFI layer -// itself can forward its own startup log (`"initializing ffi server"`, -// emitted from inside `livekit_ffi::server::FfiServer::setup`). That alone -// does not prove that records emitted by deeper Rust crates -- which is what -// shows up under `RUST_LOG=debug` as `[DEBUG libwebrtc] (...)` or as logs -// targeted at `livekit::rtc_engine::*` -- also reach the user callback. -// -// Trigger path used here (fully in-process, no network): -// -// C++ LocalAudioTrack::createLocalAudioTrack -// -> FFI request CreateAudioTrack -// -> Rust on_create_audio_track (livekit_ffi crate) -// -> LocalAudioTrack::create_audio_track (livekit crate) -// -> LkRuntime::instance() -// -> log::debug!("LkRuntime::new()") -// target = "livekit::rtc_engine::lk_runtime" -// -> PeerConnectionFactory::default() (libwebrtc-rs) -// -> installs the libwebrtc LogSink that forwards every -// internal libwebrtc message as `log::debug!(target: -// "libwebrtc", ...)`. -// -// The libwebrtc-internal logs (e.g. the `text_pcap_packet_observer.cc` lines -// the user sees under `RUST_LOG=debug`) generally fire only during real -// signaling / ICE / SDP work, which requires a live LiveKit server and so -// belong in integration tests. The deepest deterministic signal we can -// trigger from a unit test is `LkRuntime::new()` -- which is still below the -// FFI layer (it lives in the `livekit` Rust crate), so capturing it proves -// the cross-crate forwarding works. -// -// Note about std::cout: the test installs a `setLogCallback`, which causes -// the C++ logging layer to swap its spdlog sink set entirely for a callback -// sink. While the callback is installed, no SDK log output reaches stderr or -// stdout, so this test does NOT pollute GTest's console output (the only -// echoes are the deliberate ad-hoc `[ffi-log]` prints below). -TEST(FfiLoggingTest, LogsFromBelowFfiLayerReachUserCallback) { - // Defensive: start from a clean slate in case another test left the SDK - // initialised. shutdown() is a no-op when not initialised. - livekit::shutdown(); + std::lock_guard lock(mut); + // Ensure we got some logs -- not a specific value because that could change + ASSERT_GE(captured.size(), 1u); - struct Captured { - LogLevel level; - std::string logger_name; - std::string message; - }; + std::size_t info_log_count = 0; + std::size_t warn_log_count = 0; + std::size_t debug_log_count = 0; + std::size_t error_log_count = 0; - std::mutex mtx; - std::vector captured; + bool found = false; + for (const auto& entry : captured) { + if (entry.level == LogLevel::Info) { + info_log_count++; + } else if (entry.level == LogLevel::Warn) { + warn_log_count++; + } else if (entry.level == LogLevel::Debug) { + debug_log_count++; + } else if (entry.level == LogLevel::Error) { + error_log_count++; + } + } - // Install BEFORE initialize() so any startup records are observed too. - // livekit::setLogCallback([&](LogLevel level, const std::string& logger_name, const std::string& message) { - // const std::scoped_lock lock(mtx); - // std::cout << "[ffi-log] [" << logLevelName(level) << "] [" << logger_name << "] " << message << '\n'; - // captured.push_back({level, logger_name, message}); - // }); + if (true) { + std::cout << "Info logs: " << info_log_count << '\n'; + std::cout << "Warn logs: " << warn_log_count << '\n'; + std::cout << "Debug logs: " << debug_log_count << '\n'; + std::cout << "Error logs: " << error_log_count << '\n'; + } + + EXPECT_GT(info_log_count, 0); + EXPECT_GT(error_log_count, 0); + + livekit_ffi_dispose(); +} - // Trace level so the FFI logger forwards everything - ASSERT_TRUE(livekit::initialize(LogLevel::Trace, LogSink::kCallback)); +TEST_F(LoggingTest, DummyRustTest) { + livekit::shutdown(); + ASSERT_TRUE(livekit::initialize(LogLevel::Info)); + LK_LOG_INFO("Hello from C++ SDK"); // The single FFI call here -- CreateAudioTrack -- is what crosses the FFI // boundary into the `livekit` crate and triggers `LkRuntime::instance()`. - // The AudioSource ctor on its own does NOT instantiate LkRuntime; the + // The AudioSource ctor on its own does NOT instantiate LkRuntime;] the // track creation does. { auto audio_source = std::make_shared(48000, 1); @@ -458,85 +417,6 @@ TEST(FfiLoggingTest, LogsFromBelowFfiLayerReachUserCallback) { // so this sleep does not gate observability -- it just keeps things tidy. std::this_thread::sleep_for(std::chrono::milliseconds(50)); } - - // The Rust FfiLogger batches log records and flushes on a 1-second tick - // (see livekit-ffi/src/server/logger.rs FLUSH_INTERVAL). Allow generous - // headroom for slow CI machines without making the test wall-time-heavy. - const auto deadline = std::chrono::steady_clock::now() + std::chrono::seconds(5); - bool found_below_ffi_log = false; - std::string matched_target; - std::string matched_message; - while (std::chrono::steady_clock::now() < deadline) { - { - const std::scoped_lock lock(mtx); - for (const auto& entry : captured) { - // Targets demonstrably emitted from a layer BELOW livekit-ffi: - // * "livekit::..." -> livekit Rust crate (e.g. LkRuntime) - // * "libwebrtc" -> libwebrtc-rs LogSink shim - // * "webrtc"/"webrtc::..." -> direct libwebrtc-rs targets, future-proofing - // We deliberately do NOT match "livekit_ffi" here -- that's the FFI - // layer itself and would not prove cross-crate propagation. - const auto& t = entry.logger_name; - const bool is_livekit_crate = t.rfind("livekit::", 0) == 0; - const bool is_libwebrtc = (t == "libwebrtc"); - const bool is_webrtc_crate = (t == "webrtc") || t.rfind("webrtc::", 0) == 0; - if (is_livekit_crate || is_libwebrtc || is_webrtc_crate) { - found_below_ffi_log = true; - matched_target = t; - matched_message = entry.message; - break; - } - } - } - if (found_below_ffi_log) { - break; - } - std::this_thread::sleep_for(std::chrono::milliseconds(50)); - } - - EXPECT_TRUE(found_below_ffi_log) << "Expected at least one log record from below the FFI layer " - "(target starting with 'livekit::', 'libwebrtc', or 'webrtc') to " - "reach the C++ setLogCallback. This validates the " - "C++ -> FFI -> livekit-rust -> log -> FFI -> C++ chain. If this " - "fires, it likely means either capture_logs=true is not being " - "honoured by the Rust FfiLogger, or the LkRuntime weak-ref is " - "still upgrading from a previous test (in which case run this " - "test in isolation: --gtest_filter=FfiLoggingTest.LogsFromBelowFfiLayer*)."; - - if (found_below_ffi_log) { - // Ad hoc breadcrumb so test logs make it obvious WHICH below-FFI record - // was the one that satisfied the assertion. - std::cout << "[ffi-log] matched below-FFI target='" << matched_target << "' message='" << matched_message << "'" - << '\n'; - } -} - -TEST_F(LoggingTest, ConcurrentLogEmissionDoesNotCrash) { - std::atomic call_count{0}; - - livekit::setLogCallback([&](LogLevel, const std::string&, const std::string&) { call_count.fetch_add(1); }); - - livekit::setLogLevel(LogLevel::Trace); - - constexpr int kThreads = 8; - constexpr int kIterations = 200; - - std::vector threads; - threads.reserve(kThreads); - - for (int t = 0; t < kThreads; ++t) { - threads.emplace_back([&, t]() { - for (int i = 0; i < kIterations; ++i) { - LK_LOG_INFO("thread {} iteration {}", t, i); - } - }); - } - - for (auto& th : threads) { - th.join(); - } - - EXPECT_GE(call_count.load(), kThreads * kIterations); } } // namespace livekit::test From 939829fb322f8aaa828229ef5f2ac60caa96a091 Mon Sep 17 00:00:00 2001 From: Alan George Date: Mon, 18 May 2026 12:45:02 -0700 Subject: [PATCH 04/18] Logging test cleanup --- src/tests/unit/test_logging.cpp | 62 +++++++++++++++------------------ 1 file changed, 29 insertions(+), 33 deletions(-) diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index b1d99db9..325b2538 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -41,6 +41,34 @@ namespace { // reach setLogCallback() the same way they do in production. extern "C" void testFfiCallback(const uint8_t* buf, size_t len) { LivekitFfiCallback(buf, len); } +// Utility function to convert LogLevel to a string for debug printing +const char* logLevelName(LogLevel level) { + switch (level) { + case LogLevel::Trace: + return "TRACE"; + case LogLevel::Debug: + return "DEBUG"; + case LogLevel::Info: + return "INFO"; + case LogLevel::Warn: + return "WARN"; + case LogLevel::Error: + return "ERROR"; + case LogLevel::Critical: + return "CRITICAL"; + case LogLevel::Off: + return "OFF"; + } + return "?"; +} + +// Used to capture log records and verify them in tests +struct LogRecord { + LogLevel level; + std::string logger_name; + std::string message; +}; + } // namespace class LoggingTest : public ::testing::Test { @@ -288,38 +316,6 @@ TEST_F(LoggingTest, ConcurrentLogEmissionDoesNotCrash) { // Rust FFI -> C++ log forwarding // --------------------------------------------------------------------------- -namespace { - -// Utility function to convert LogLevel to a string for debug printing -const char* logLevelName(LogLevel level) { - switch (level) { - case LogLevel::Trace: - return "TRACE"; - case LogLevel::Debug: - return "DEBUG"; - case LogLevel::Info: - return "INFO"; - case LogLevel::Warn: - return "WARN"; - case LogLevel::Error: - return "ERROR"; - case LogLevel::Critical: - return "CRITICAL"; - case LogLevel::Off: - return "OFF"; - } - return "?"; -} - -} // namespace - -// Used by multiple tests -struct Captured { - LogLevel level; - std::string logger_name; - std::string message; -}; - TEST_F(LoggingTest, RustLogsAreForwarded) { // User toggle for debugging this unit test bool print_logs = true; @@ -328,7 +324,7 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { livekit::shutdown(); std::mutex mut; std::condition_variable cv; - std::vector captured; + std::vector captured; bool decode_error_received = false; livekit::setLogLevel(LogLevel::Trace); From bfd09f49fc9fb9208c5c76627da637b42d6a932e Mon Sep 17 00:00:00 2001 From: Alan George Date: Mon, 18 May 2026 13:27:35 -0700 Subject: [PATCH 05/18] Try latest FFI release --- .github/workflows/tests.yml | 16 +++++++++++++--- client-sdk-rust | 2 +- src/tests/unit/test_logging.cpp | 13 ++++++------- 3 files changed, 20 insertions(+), 11 deletions(-) diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 733017d1..0c338183 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -197,7 +197,9 @@ jobs: # ---------- Run unit tests ---------- - name: Run unit tests (Unix) + id: unit_tests if: runner.os != 'Windows' + continue-on-error: true timeout-minutes: 1 shell: bash run: | @@ -205,7 +207,9 @@ jobs: --gtest_output=xml:build-release/unit-test-results.xml - name: Run unit tests (Windows) + id: unit_tests if: runner.os == 'Windows' + continue-on-error: true timeout-minutes: 1 shell: pwsh run: | @@ -214,7 +218,7 @@ jobs: # ---------- Install + start livekit-server for integration tests ---------- - name: Install livekit-server and lk CLI - if: matrix.e2e-testing + if: matrix.e2e-testing && !cancelled() shell: bash run: | set -euxo pipefail @@ -231,7 +235,7 @@ jobs: lk --version - name: Start livekit-server - if: matrix.e2e-testing + if: matrix.e2e-testing && !cancelled() shell: bash env: LIVEKIT_CONFIG: "enable_data_tracks: true" @@ -255,7 +259,7 @@ jobs: exit 1 - name: Run integration tests - if: matrix.e2e-testing + if: matrix.e2e-testing && !cancelled() timeout-minutes: 5 shell: bash env: @@ -280,6 +284,12 @@ jobs: shell: bash run: tail -n 500 livekit-server.log || true + - name: Check unit test result + if: always() && !cancelled() && steps.unit_tests.outcome == 'failure' + run: | + echo "::error::Unit tests failed" + exit 1 + # ---------- Upload results ---------- - name: Upload test results if: always() diff --git a/client-sdk-rust b/client-sdk-rust index 8d4d069a..b7d8d12a 160000 --- a/client-sdk-rust +++ b/client-sdk-rust @@ -1 +1 @@ -Subproject commit 8d4d069ac6b47e610160bf44b8891a730ce91154 +Subproject commit b7d8d12a0fdd75d2a9cf3279b93ddd62adff2beb diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index 325b2538..71d2547a 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -325,7 +325,7 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { std::mutex mut; std::condition_variable cv; std::vector captured; - bool decode_error_received = false; + bool error_received = false; livekit::setLogLevel(LogLevel::Trace); livekit::setLogCallback([&](LogLevel level, const std::string& logger_name, const std::string& message) { @@ -335,10 +335,9 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { std::cout << "[Captured Rust log] [" << logLevelName(level) << "] [" << logger_name << "] " << message << '\n'; } - // Check for specific known error message for condition variable wait. Otherwise we have to sleep a second - // for the 1Hz flush interval, which slows this test down unnecessarily - if (level == LogLevel::Error && message.find("failed to decode request") != std::string::npos) { - decode_error_received = true; + // Wake as soon as any error is forwarded so we avoid waiting for the 1Hz flush interval. + if (level == LogLevel::Error) { + error_received = true; cv.notify_one(); } }); @@ -357,7 +356,7 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { // Wait for the error log to be captured { std::unique_lock lock(mut); - ASSERT_TRUE(cv.wait_for(lock, std::chrono::seconds(1), [&] { return decode_error_received; })); + ASSERT_TRUE(cv.wait_for(lock, std::chrono::seconds(1), [&] { return error_received; })); } std::lock_guard lock(mut); @@ -389,7 +388,7 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { std::cout << "Error logs: " << error_log_count << '\n'; } - EXPECT_GT(info_log_count, 0); + EXPECT_GT(debug_log_count, 0); EXPECT_GT(error_log_count, 0); livekit_ffi_dispose(); From 880df99298af76560df6955a1edbd136be1ac9d4 Mon Sep 17 00:00:00 2001 From: Alan George Date: Mon, 18 May 2026 14:34:05 -0700 Subject: [PATCH 06/18] Cleanup how cv works --- src/tests/unit/test_logging.cpp | 77 +++++++++++++++++++-------------- 1 file changed, 45 insertions(+), 32 deletions(-) diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index 71d2547a..ac3e84a1 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -322,29 +322,63 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { // Start from clean slate livekit::shutdown(); + std::mutex mut; - std::condition_variable cv; std::vector captured; - bool error_received = false; + std::condition_variable cv; + + // Used to track how many logs of each level have been forwarded, + // and used by the condition variable to immedtiate unblock once the buffered logs are consumed + std::size_t info_log_count = 0; + std::size_t warn_log_count = 0; + std::size_t debug_log_count = 0; + std::size_t error_log_count = 0; + + const auto required_rust_logs_received = [&] { + return debug_log_count > 0 && warn_log_count > 0 && error_log_count > 0; + }; livekit::setLogLevel(LogLevel::Trace); livekit::setLogCallback([&](LogLevel level, const std::string& logger_name, const std::string& message) { const std::scoped_lock lock(mut); captured.push_back({level, logger_name, message}); if (print_logs) { - std::cout << "[Captured Rust log] [" << logLevelName(level) << "] [" << logger_name << "] " << message << '\n'; + std::cout << "[Forwarded Rust log] [" << logLevelName(level) << "] [" << logger_name << "] " << message << '\n'; } - // Wake as soon as any error is forwarded so we avoid waiting for the 1Hz flush interval. - if (level == LogLevel::Error) { - error_received = true; + switch (level) { + case LogLevel::Info: + ++info_log_count; + break; + case LogLevel::Warn: + ++warn_log_count; + break; + case LogLevel::Debug: + ++debug_log_count; + break; + case LogLevel::Error: + ++error_log_count; + break; + default: + break; + } + + // Wake once init (debug), invalid handle (warn), and bad request (error) have all been forwarded. + if (required_rust_logs_received()) { cv.notify_one(); } }); + // Induce a Rust-side debug level log + // Via FFI initialization messages ASSERT_NO_THROW(livekit_ffi_initialize(testFfiCallback, true, "cpp-test", "1.0.0")); - // Induce a Rust-side error log via an invalid protobuf payload + // Induce a Rust-wise warning level log + // Via dropping an invalid handle + livekit_ffi_drop_handle(12345); + + // Induce a Rust-side error level log + // Via an invalid protobuf payload { std::vector data(100); const uint8_t* res_ptr = nullptr; @@ -353,41 +387,20 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { EXPECT_EQ(handle, INVALID_HANDLE); } - // Wait for the error log to be captured + // Wait for the required logs to be forwarded { std::unique_lock lock(mut); - ASSERT_TRUE(cv.wait_for(lock, std::chrono::seconds(1), [&] { return error_received; })); - } - - std::lock_guard lock(mut); - // Ensure we got some logs -- not a specific value because that could change - ASSERT_GE(captured.size(), 1u); - - std::size_t info_log_count = 0; - std::size_t warn_log_count = 0; - std::size_t debug_log_count = 0; - std::size_t error_log_count = 0; - - bool found = false; - for (const auto& entry : captured) { - if (entry.level == LogLevel::Info) { - info_log_count++; - } else if (entry.level == LogLevel::Warn) { - warn_log_count++; - } else if (entry.level == LogLevel::Debug) { - debug_log_count++; - } else if (entry.level == LogLevel::Error) { - error_log_count++; - } + ASSERT_TRUE(cv.wait_for(lock, std::chrono::seconds(1), required_rust_logs_received)); } - if (true) { + if (print_logs) { std::cout << "Info logs: " << info_log_count << '\n'; std::cout << "Warn logs: " << warn_log_count << '\n'; std::cout << "Debug logs: " << debug_log_count << '\n'; std::cout << "Error logs: " << error_log_count << '\n'; } + EXPECT_GT(warn_log_count, 0); EXPECT_GT(debug_log_count, 0); EXPECT_GT(error_log_count, 0); From d1f7d190febc288347abaf069491001b39d1646d Mon Sep 17 00:00:00 2001 From: Alan George Date: Mon, 18 May 2026 15:12:38 -0700 Subject: [PATCH 07/18] Cleaner info inducing --- src/tests/CMakeLists.txt | 1 - src/tests/unit/test_logging.cpp | 57 ++++++++++++++++----------------- 2 files changed, 28 insertions(+), 30 deletions(-) diff --git a/src/tests/CMakeLists.txt b/src/tests/CMakeLists.txt index ca40bec7..2bd0c09e 100644 --- a/src/tests/CMakeLists.txt +++ b/src/tests/CMakeLists.txt @@ -62,7 +62,6 @@ if(UNIT_TEST_SOURCES) target_link_libraries(livekit_unit_tests PRIVATE livekit - livekit_ffi spdlog::spdlog ${LIVEKIT_PROTOBUF_TARGET} GTest::gtest_main diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index ac3e84a1..e4252a9b 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -29,18 +29,15 @@ #include #include +#include "ffi.pb.h" #include "ffi_client.h" -#include "livekit_ffi.h" +#include "livekit/ffi_handle.h" #include "lk_log.h" namespace livekit::test { namespace { -// FFI event entry point for tests. Forwards to the SDK handler so log batches -// reach setLogCallback() the same way they do in production. -extern "C" void testFfiCallback(const uint8_t* buf, size_t len) { LivekitFfiCallback(buf, len); } - // Utility function to convert LogLevel to a string for debug printing const char* logLevelName(LogLevel level) { switch (level) { @@ -318,7 +315,8 @@ TEST_F(LoggingTest, ConcurrentLogEmissionDoesNotCrash) { TEST_F(LoggingTest, RustLogsAreForwarded) { // User toggle for debugging this unit test - bool print_logs = true; + // Prints all the forwarded logs to the console + bool print_logs = false; // Start from clean slate livekit::shutdown(); @@ -334,8 +332,8 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { std::size_t debug_log_count = 0; std::size_t error_log_count = 0; - const auto required_rust_logs_received = [&] { - return debug_log_count > 0 && warn_log_count > 0 && error_log_count > 0; + const auto all_rust_logs_received = [&] { + return info_log_count > 0 && debug_log_count > 0 && warn_log_count > 0 && error_log_count > 0; }; livekit::setLogLevel(LogLevel::Trace); @@ -363,34 +361,34 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { break; } - // Wake once init (debug), invalid handle (warn), and bad request (error) have all been forwarded. - if (required_rust_logs_received()) { + if (all_rust_logs_received()) { cv.notify_one(); } }); - // Induce a Rust-side debug level log - // Via FFI initialization messages - ASSERT_NO_THROW(livekit_ffi_initialize(testFfiCallback, true, "cpp-test", "1.0.0")); - - // Induce a Rust-wise warning level log - // Via dropping an invalid handle - livekit_ffi_drop_handle(12345); - - // Induce a Rust-side error level log - // Via an invalid protobuf payload + // Induce a Rust-side debug level log via FFI initialization. + ASSERT_TRUE(FfiClient::instance().initialize(true)); + + // Induce Rust-side info level log + // Starts an async room connect so livekit-api logs at INFO ("connecting to ...") before the + // attempt fails + proto::FfiRequest req; + auto* connect = req.mutable_connect(); + connect->set_url("ws://127.0.0.1:7880"); + // JWT-shaped token (format only); connection is expected to fail. + connect->set_token("eyJhbGciOiJIUzI1NiJ9.eyJleHAiOjB9.x"); + connect->mutable_options()->set_connect_timeout_ms(500); + ASSERT_NO_THROW(FfiClient::instance().sendRequest(req)); + + // Induce a Rust-side warning via dropping an invalid handle. { - std::vector data(100); - const uint8_t* res_ptr = nullptr; - size_t res_len = 0; - const auto handle = livekit_ffi_request(data.data(), data.size(), &res_ptr, &res_len); - EXPECT_EQ(handle, INVALID_HANDLE); + const FfiHandle invalid_handle(12345); + (void)invalid_handle; } - // Wait for the required logs to be forwarded { std::unique_lock lock(mut); - ASSERT_TRUE(cv.wait_for(lock, std::chrono::seconds(1), required_rust_logs_received)); + ASSERT_TRUE(cv.wait_for(lock, std::chrono::seconds(2), all_rust_logs_received)); } if (print_logs) { @@ -400,11 +398,12 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { std::cout << "Error logs: " << error_log_count << '\n'; } - EXPECT_GT(warn_log_count, 0); EXPECT_GT(debug_log_count, 0); + EXPECT_GT(info_log_count, 0); + EXPECT_GT(warn_log_count, 0); EXPECT_GT(error_log_count, 0); - livekit_ffi_dispose(); + FfiClient::instance().shutdown(); } TEST_F(LoggingTest, DummyRustTest) { From 40821202b50a074229cff7e5822004fe2cb59d4f Mon Sep 17 00:00:00 2001 From: Alan George Date: Mon, 18 May 2026 15:20:34 -0700 Subject: [PATCH 08/18] Cleanup tests file --- .github/workflows/tests.yml | 9 --------- 1 file changed, 9 deletions(-) diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 0c338183..5d179738 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -197,9 +197,7 @@ jobs: # ---------- Run unit tests ---------- - name: Run unit tests (Unix) - id: unit_tests if: runner.os != 'Windows' - continue-on-error: true timeout-minutes: 1 shell: bash run: | @@ -207,7 +205,6 @@ jobs: --gtest_output=xml:build-release/unit-test-results.xml - name: Run unit tests (Windows) - id: unit_tests if: runner.os == 'Windows' continue-on-error: true timeout-minutes: 1 @@ -284,12 +281,6 @@ jobs: shell: bash run: tail -n 500 livekit-server.log || true - - name: Check unit test result - if: always() && !cancelled() && steps.unit_tests.outcome == 'failure' - run: | - echo "::error::Unit tests failed" - exit 1 - # ---------- Upload results ---------- - name: Upload test results if: always() From 1962627241c368e368f1f5594e951f6f5ad6b5c0 Mon Sep 17 00:00:00 2001 From: Alan George Date: Mon, 18 May 2026 15:22:04 -0700 Subject: [PATCH 09/18] Undo test file changes --- .github/workflows/tests.yml | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 5d179738..733017d1 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -206,7 +206,6 @@ jobs: - name: Run unit tests (Windows) if: runner.os == 'Windows' - continue-on-error: true timeout-minutes: 1 shell: pwsh run: | @@ -215,7 +214,7 @@ jobs: # ---------- Install + start livekit-server for integration tests ---------- - name: Install livekit-server and lk CLI - if: matrix.e2e-testing && !cancelled() + if: matrix.e2e-testing shell: bash run: | set -euxo pipefail @@ -232,7 +231,7 @@ jobs: lk --version - name: Start livekit-server - if: matrix.e2e-testing && !cancelled() + if: matrix.e2e-testing shell: bash env: LIVEKIT_CONFIG: "enable_data_tracks: true" @@ -256,7 +255,7 @@ jobs: exit 1 - name: Run integration tests - if: matrix.e2e-testing && !cancelled() + if: matrix.e2e-testing timeout-minutes: 5 shell: bash env: From a7f99c253cb8f5e35942cc35852efb61bc47f68d Mon Sep 17 00:00:00 2001 From: Alan George Date: Mon, 18 May 2026 20:02:14 -0700 Subject: [PATCH 10/18] Better testing of level mapping --- src/tests/unit/test_logging.cpp | 126 +++++++++++++------------------- 1 file changed, 50 insertions(+), 76 deletions(-) diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index e4252a9b..a5c2b57a 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -101,14 +101,8 @@ TEST_F(LoggingTest, DefaultLogLevelIsInfo) { EXPECT_EQ(livekit::getLogLevel(), L // --------------------------------------------------------------------------- TEST_F(LoggingTest, CallbackReceivesLogMessages) { - struct Captured { - LogLevel level; - std::string logger_name; - std::string message; - }; - std::mutex mtx; - std::vector captured; + std::vector captured; livekit::setLogCallback([&](LogLevel level, const std::string& logger_name, const std::string& message) { std::lock_guard lock(mtx); @@ -313,34 +307,33 @@ TEST_F(LoggingTest, ConcurrentLogEmissionDoesNotCrash) { // Rust FFI -> C++ log forwarding // --------------------------------------------------------------------------- +// Starts an async room connect; livekit-api logs INFO ("connecting to ...") and the attempt +// eventually fails with ERROR. +void sendFailedConnectRequest() { + proto::FfiRequest req; + auto* connect = req.mutable_connect(); + connect->set_url("ws://127.0.0.1:7880"); + // JWT-shaped token (format only); connection is expected to fail. + connect->set_token("eyJhbGciOiJIUzI1NiJ9.eyJleHAiOjB9.x"); + connect->mutable_options()->set_connect_timeout_ms(500); + FfiClient::instance().sendRequest(req); +} + TEST_F(LoggingTest, RustLogsAreForwarded) { - // User toggle for debugging this unit test - // Prints all the forwarded logs to the console - bool print_logs = false; + constexpr bool kPrintLogs = false; - // Start from clean slate livekit::shutdown(); std::mutex mut; - std::vector captured; std::condition_variable cv; - - // Used to track how many logs of each level have been forwarded, - // and used by the condition variable to immedtiate unblock once the buffered logs are consumed std::size_t info_log_count = 0; std::size_t warn_log_count = 0; std::size_t debug_log_count = 0; std::size_t error_log_count = 0; - const auto all_rust_logs_received = [&] { - return info_log_count > 0 && debug_log_count > 0 && warn_log_count > 0 && error_log_count > 0; - }; - - livekit::setLogLevel(LogLevel::Trace); livekit::setLogCallback([&](LogLevel level, const std::string& logger_name, const std::string& message) { const std::scoped_lock lock(mut); - captured.push_back({level, logger_name, message}); - if (print_logs) { + if (kPrintLogs) { std::cout << "[Forwarded Rust log] [" << logLevelName(level) << "] [" << logger_name << "] " << message << '\n'; } @@ -360,70 +353,51 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { default: break; } - - if (all_rust_logs_received()) { - cv.notify_one(); - } + cv.notify_all(); }); - // Induce a Rust-side debug level log via FFI initialization. - ASSERT_TRUE(FfiClient::instance().initialize(true)); - - // Induce Rust-side info level log - // Starts an async room connect so livekit-api logs at INFO ("connecting to ...") before the - // attempt fails - proto::FfiRequest req; - auto* connect = req.mutable_connect(); - connect->set_url("ws://127.0.0.1:7880"); - // JWT-shaped token (format only); connection is expected to fail. - connect->set_token("eyJhbGciOiJIUzI1NiJ9.eyJleHAiOjB9.x"); - connect->mutable_options()->set_connect_timeout_ms(500); - ASSERT_NO_THROW(FfiClient::instance().sendRequest(req)); + const auto wait_for = [&](const auto& predicate) { + std::unique_lock lock(mut); + return cv.wait_for(lock, std::chrono::seconds(2), predicate); + }; - // Induce a Rust-side warning via dropping an invalid handle. + // Stage 1: Error — only error-level Rust logs should be forwarded. + livekit::setLogLevel(LogLevel::Error); + ASSERT_TRUE(FfiClient::instance().initialize(true)); + sendFailedConnectRequest(); + ASSERT_TRUE(wait_for([&] { return error_log_count > 0; })); + EXPECT_GT(error_log_count, 0u); + EXPECT_EQ(debug_log_count, 0u); + EXPECT_EQ(info_log_count, 0u); + EXPECT_EQ(warn_log_count, 0u); + + // Stage 2: Warn — invalid handle drop produces a warning. + livekit::setLogLevel(LogLevel::Warn); + const std::size_t error_before_warn = error_log_count; { const FfiHandle invalid_handle(12345); (void)invalid_handle; } - - { - std::unique_lock lock(mut); - ASSERT_TRUE(cv.wait_for(lock, std::chrono::seconds(2), all_rust_logs_received)); - } - - if (print_logs) { - std::cout << "Info logs: " << info_log_count << '\n'; - std::cout << "Warn logs: " << warn_log_count << '\n'; - std::cout << "Debug logs: " << debug_log_count << '\n'; - std::cout << "Error logs: " << error_log_count << '\n'; - } - - EXPECT_GT(debug_log_count, 0); - EXPECT_GT(info_log_count, 0); - EXPECT_GT(warn_log_count, 0); - EXPECT_GT(error_log_count, 0); - + ASSERT_TRUE(wait_for([&] { return warn_log_count > 0; })); + EXPECT_GT(warn_log_count, 0u); + EXPECT_GE(error_log_count, error_before_warn); + + // Stage 3: Info — connect logs "connecting to ..." at INFO before failing. + livekit::setLogLevel(LogLevel::Info); + sendFailedConnectRequest(); + ASSERT_TRUE(wait_for([&] { return info_log_count > 0; })); + EXPECT_GT(info_log_count, 0u); + + // Stage 4: Debug — re-init FFI to emit initialization debug logs. + livekit::setLogLevel(LogLevel::Debug); FfiClient::instance().shutdown(); -} + ASSERT_TRUE(FfiClient::instance().initialize(true)); + ASSERT_TRUE(wait_for([&] { return debug_log_count > 0; })); + EXPECT_GT(debug_log_count, 0u); -TEST_F(LoggingTest, DummyRustTest) { - livekit::shutdown(); - ASSERT_TRUE(livekit::initialize(LogLevel::Info)); - LK_LOG_INFO("Hello from C++ SDK"); + // Trace is not logged in Rust at time of writing - // The single FFI call here -- CreateAudioTrack -- is what crosses the FFI - // boundary into the `livekit` crate and triggers `LkRuntime::instance()`. - // The AudioSource ctor on its own does NOT instantiate LkRuntime;] the - // track creation does. - { - auto audio_source = std::make_shared(48000, 1); - auto track = LocalAudioTrack::createLocalAudioTrack("ffi-log-probe", audio_source); - ASSERT_NE(track, nullptr); - // Hold the handles briefly so any synchronous Rust-side debug logs land - // before the strong refs drop. The FFI logger flushes on a 1s interval, - // so this sleep does not gate observability -- it just keeps things tidy. - std::this_thread::sleep_for(std::chrono::milliseconds(50)); - } + FfiClient::instance().shutdown(); } } // namespace livekit::test From 2273f9a3cb549fd05640105c24239d9a9194e356 Mon Sep 17 00:00:00 2001 From: Alan George Date: Mon, 18 May 2026 20:31:47 -0700 Subject: [PATCH 11/18] Maybe fix crash --- src/livekit.cpp | 2 -- src/tests/unit/test_logging.cpp | 5 ++++- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/src/livekit.cpp b/src/livekit.cpp index dc8c4a17..624d5553 100644 --- a/src/livekit.cpp +++ b/src/livekit.cpp @@ -28,8 +28,6 @@ bool initialize(const LogLevel& level, const LogSink& log_sink) { return ffi_client.initialize(true); } -bool isInitialized() { return FfiClient::instance().isInitialized(); } - void shutdown() { FfiClient::instance().shutdown(); detail::shutdownLogger(); diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index a5c2b57a..cd1703e7 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -70,10 +70,13 @@ struct LogRecord { class LoggingTest : public ::testing::Test { protected: - void SetUp() override { livekit::initialize(); } + void SetUp() override { livekit::setLogLevel(LogLevel::Info); } void TearDown() override { livekit::setLogCallback(nullptr); + if (FfiClient::instance().isInitialized()) { + FfiClient::instance().shutdown(); + } livekit::shutdown(); } }; From 8114b4721851238010bd0ef0beb257555938c95d Mon Sep 17 00:00:00 2001 From: Alan George Date: Mon, 18 May 2026 21:20:18 -0700 Subject: [PATCH 12/18] Maybe fix race --- src/tests/unit/test_logging.cpp | 49 ++++++++++++--------------------- 1 file changed, 17 insertions(+), 32 deletions(-) diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index cd1703e7..f4c0abf0 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -334,6 +334,11 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { std::size_t debug_log_count = 0; std::size_t error_log_count = 0; + const auto all_rust_logs_received = [&] { + return info_log_count > 0 && debug_log_count > 0 && warn_log_count > 0 && error_log_count > 0; + }; + + livekit::setLogLevel(LogLevel::Trace); livekit::setLogCallback([&](LogLevel level, const std::string& logger_name, const std::string& message) { const std::scoped_lock lock(mut); if (kPrintLogs) { @@ -356,49 +361,29 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { default: break; } - cv.notify_all(); - }); - const auto wait_for = [&](const auto& predicate) { - std::unique_lock lock(mut); - return cv.wait_for(lock, std::chrono::seconds(2), predicate); - }; + if (all_rust_logs_received()) { + cv.notify_all(); + } + }); - // Stage 1: Error — only error-level Rust logs should be forwarded. - livekit::setLogLevel(LogLevel::Error); + // Stimuli: init (debug), connect (info + error), invalid handle drop (warn). ASSERT_TRUE(FfiClient::instance().initialize(true)); sendFailedConnectRequest(); - ASSERT_TRUE(wait_for([&] { return error_log_count > 0; })); - EXPECT_GT(error_log_count, 0u); - EXPECT_EQ(debug_log_count, 0u); - EXPECT_EQ(info_log_count, 0u); - EXPECT_EQ(warn_log_count, 0u); - - // Stage 2: Warn — invalid handle drop produces a warning. - livekit::setLogLevel(LogLevel::Warn); - const std::size_t error_before_warn = error_log_count; { const FfiHandle invalid_handle(12345); (void)invalid_handle; } - ASSERT_TRUE(wait_for([&] { return warn_log_count > 0; })); - EXPECT_GT(warn_log_count, 0u); - EXPECT_GE(error_log_count, error_before_warn); - // Stage 3: Info — connect logs "connecting to ..." at INFO before failing. - livekit::setLogLevel(LogLevel::Info); - sendFailedConnectRequest(); - ASSERT_TRUE(wait_for([&] { return info_log_count > 0; })); - EXPECT_GT(info_log_count, 0u); + { + std::unique_lock lock(mut); + ASSERT_TRUE(cv.wait_for(lock, std::chrono::seconds(3), all_rust_logs_received)); + } - // Stage 4: Debug — re-init FFI to emit initialization debug logs. - livekit::setLogLevel(LogLevel::Debug); - FfiClient::instance().shutdown(); - ASSERT_TRUE(FfiClient::instance().initialize(true)); - ASSERT_TRUE(wait_for([&] { return debug_log_count > 0; })); EXPECT_GT(debug_log_count, 0u); - - // Trace is not logged in Rust at time of writing + EXPECT_GT(info_log_count, 0u); + EXPECT_GT(warn_log_count, 0u); + EXPECT_GT(error_log_count, 0u); FfiClient::instance().shutdown(); } From fe5ab0e808b1b91ac52bda7a6ddca16969ab02ad Mon Sep 17 00:00:00 2001 From: Alan George Date: Tue, 19 May 2026 09:33:54 -0700 Subject: [PATCH 13/18] Better test setup, fix FFI compiler issue --- src/ffi_client.cpp | 2 +- src/ffi_client.h | 2 +- src/tests/unit/test_logging.cpp | 14 +++++++++++--- 3 files changed, 13 insertions(+), 5 deletions(-) diff --git a/src/ffi_client.cpp b/src/ffi_client.cpp index 758fd1a6..70bf5288 100644 --- a/src/ffi_client.cpp +++ b/src/ffi_client.cpp @@ -269,7 +269,7 @@ void FfiClient::PushEvent(const proto::FfiEvent& event) const { } } -LIVEKIT_INTERNAL_API void LivekitFfiCallback(const uint8_t* buf, size_t len) { +extern "C" LIVEKIT_INTERNAL_API void LivekitFfiCallback(const uint8_t* buf, size_t len) { proto::FfiEvent event; event.ParseFromArray(buf, static_cast(len)); // TODO: this fixes for now, what if len exceeds int? diff --git a/src/ffi_client.h b/src/ffi_client.h index ef948000..e9bd3e3c 100644 --- a/src/ffi_client.h +++ b/src/ffi_client.h @@ -58,7 +58,7 @@ extern "C" void livekit_ffi_initialize(FfiCallbackFn cb, bool capture_logs, cons extern "C" void livekit_ffi_dispose(); -LIVEKIT_INTERNAL_API extern "C" void LivekitFfiCallback(const uint8_t* buf, size_t len); +extern "C" LIVEKIT_INTERNAL_API void LivekitFfiCallback(const uint8_t* buf, size_t len); // The FfiClient is used to communicate with the FFI interface of the Rust SDK // We use the generated protocol messages to facilitate the communication. diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index f4c0abf0..74bc69da 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -310,8 +310,7 @@ TEST_F(LoggingTest, ConcurrentLogEmissionDoesNotCrash) { // Rust FFI -> C++ log forwarding // --------------------------------------------------------------------------- -// Starts an async room connect; livekit-api logs INFO ("connecting to ...") and the attempt -// eventually fails with ERROR. +// Starts an async room connect so livekit-api logs INFO ("connecting to ..."). void sendFailedConnectRequest() { proto::FfiRequest req; auto* connect = req.mutable_connect(); @@ -322,6 +321,14 @@ void sendFailedConnectRequest() { FfiClient::instance().sendRequest(req); } +void sendInvalidFfiRequest() { + proto::FfiRequest req; + auto* set_subscribed = req.mutable_set_subscribed(); + set_subscribed->set_subscribe(true); + set_subscribed->set_publication_handle(12345); + (void)FfiClient::instance().sendRequest(req); +} + TEST_F(LoggingTest, RustLogsAreForwarded) { constexpr bool kPrintLogs = false; @@ -367,9 +374,10 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { } }); - // Stimuli: init (debug), connect (info + error), invalid handle drop (warn). + // Stimuli: init (debug), connect (info), invalid request (error), invalid handle drop (warn). ASSERT_TRUE(FfiClient::instance().initialize(true)); sendFailedConnectRequest(); + ASSERT_THROW(sendInvalidFfiRequest(), std::runtime_error); { const FfiHandle invalid_handle(12345); (void)invalid_handle; From 545ed714ed86f7b3ba0dc35fc9a3252a7af9bbb7 Mon Sep 17 00:00:00 2001 From: Alan George Date: Tue, 19 May 2026 10:20:11 -0700 Subject: [PATCH 14/18] Deprecate LogSink initialize signature --- include/livekit/livekit.h | 16 ++++++++++++++-- src/livekit.cpp | 5 +++++ 2 files changed, 19 insertions(+), 2 deletions(-) diff --git a/include/livekit/livekit.h b/include/livekit/livekit.h index f7906c42..a60b4a25 100644 --- a/include/livekit/livekit.h +++ b/include/livekit/livekit.h @@ -43,7 +43,8 @@ namespace livekit { /// The log sink to use for SDK messages. -enum class LogSink { +/// @deprecated Use livekit::setLogCallback instead to register a custom log callback +enum class [[deprecated("Use livekit::setLogCallback instead to register a custom log callback")]] LogSink { /// Log messages to the console. kConsole = 0, /// Log messages to a callback function. @@ -60,7 +61,18 @@ enum class LogSink { /// @param log_sink The log sink to use for SDK messages (default: Console). /// @returns true if initialization happened on this call, false if it was /// already initialized. -LIVEKIT_API bool initialize(const LogLevel& level = LogLevel::Info, const LogSink& log_sink = LogSink::kConsole); +/// @deprecated Use livekit::setLogCallback instead to register a custom log callback +[[deprecated("Use livekit::setLogCallback instead to register a custom log callback")]] LIVEKIT_API bool initialize( + const LogLevel& level, const LogSink& log_sink); + +/// Initialize the LiveKit SDK. +/// +/// This **must be the first LiveKit API called** in the process. +/// It configures global SDK state. +/// +/// @param level Minimum log level for SDK messages (default: Info). +/// Use setLogLevel() to change at runtime. +LIVEKIT_API bool initialize(const LogLevel& level = LogLevel::Info); /// Shut down the LiveKit SDK. /// diff --git a/src/livekit.cpp b/src/livekit.cpp index 624d5553..9b05552b 100644 --- a/src/livekit.cpp +++ b/src/livekit.cpp @@ -22,6 +22,11 @@ namespace livekit { bool initialize(const LogLevel& level, const LogSink& log_sink) { + (void)log_sink; + return initialize(level); +} + +bool initialize(const LogLevel& level) { // Initializes logger if singleton instance is not already initialized setLogLevel(level); auto& ffi_client = FfiClient::instance(); From d3ce627bdcea19796caa797278b0bb8df2e1abfa Mon Sep 17 00:00:00 2001 From: Alan George Date: Tue, 19 May 2026 10:32:13 -0700 Subject: [PATCH 15/18] Only acquire the mutex once for FFI log forwarding --- src/ffi_client.cpp | 6 ++++-- src/lk_log.h | 10 +++------- src/logging.cpp | 6 ++---- 3 files changed, 9 insertions(+), 13 deletions(-) diff --git a/src/ffi_client.cpp b/src/ffi_client.cpp index 70bf5288..8bffd5b2 100644 --- a/src/ffi_client.cpp +++ b/src/ffi_client.cpp @@ -276,10 +276,12 @@ extern "C" LIVEKIT_INTERNAL_API void LivekitFfiCallback(const uint8_t* buf, size // Forward any FFI logs to the SDK logger if (event.has_logs()) { + // Note: explicitly acquiring the logger here to avoid mutex acquires per-message + auto logger = detail::getLogger(); for (const auto& rec : event.logs().records()) { - detail::forwardFfiLog(toSpdlogLevel(rec.level()), rec.target(), rec.message()); + detail::forwardFfiLog(logger, toSpdlogLevel(rec.level()), rec.target(), rec.message()); } - return; // No need to queue the logs + return; // No need to queue the log event from here } // We are in a unrecoverable state, terminate the process diff --git a/src/lk_log.h b/src/lk_log.h index 3c361ac7..ef10880e 100644 --- a/src/lk_log.h +++ b/src/lk_log.h @@ -35,13 +35,9 @@ LIVEKIT_INTERNAL_API std::shared_ptr getLogger(); LIVEKIT_INTERNAL_API void shutdownLogger(); /// Forward a single record received from the Rust FFI log bridge into the -/// SDK's spdlog sinks. The supplied @p target is preserved as the -/// `logger_name` exposed to any user-installed `setLogCallback`, allowing -/// callers to distinguish between e.g. "livekit", "libwebrtc", -/// "tokio-tungstenite", etc. -/// -/// Filtering uses the same level set via `livekit::setLogLevel`. -LIVEKIT_INTERNAL_API void forwardFfiLog(LogLevel level, const std::string& target, const std::string& message); +/// supplied logger's spdlog sinks +LIVEKIT_INTERNAL_API void forwardFfiLog(const std::shared_ptr& logger, LogLevel level, + const std::string& target, const std::string& message); } // namespace livekit::detail diff --git a/src/logging.cpp b/src/logging.cpp index 7802f1f8..3c2332ad 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -111,10 +111,8 @@ void shutdownLogger() { } } -void forwardFfiLog(LogLevel level, const std::string& target, const std::string& message) { - // Snapshot the current logger via shared_ptr so that a concurrent - // setLogCallback() / shutdownLogger() cannot race with our sink iteration. - auto logger = getLogger(); +void forwardFfiLog(const std::shared_ptr& logger, LogLevel level, const std::string& target, + const std::string& message) { const auto spd_level = toSpdlogLevel(level); if (!logger->should_log(spd_level)) { return; From e8a039f649e47dc3bbe1a8cdc63141f54e9b2e2f Mon Sep 17 00:00:00 2001 From: Alan George Date: Tue, 19 May 2026 10:53:34 -0700 Subject: [PATCH 16/18] Additional test to ensure logs aren't forwarded --- src/tests/unit/test_logging.cpp | 38 ++++++++++++++++++++++++++++++++- 1 file changed, 37 insertions(+), 1 deletion(-) diff --git a/src/tests/unit/test_logging.cpp b/src/tests/unit/test_logging.cpp index 74bc69da..7428d0ae 100644 --- a/src/tests/unit/test_logging.cpp +++ b/src/tests/unit/test_logging.cpp @@ -23,7 +23,6 @@ #include #include #include -#include #include #include #include @@ -396,4 +395,41 @@ TEST_F(LoggingTest, RustLogsAreForwarded) { FfiClient::instance().shutdown(); } +TEST_F(LoggingTest, RustLogsAreSuppressedWhenOff) { + livekit::shutdown(); + + std::mutex mut; + std::condition_variable cv; + std::size_t log_count = 0; + + livekit::setLogLevel(LogLevel::Off); + livekit::setLogCallback([&](LogLevel, const std::string&, const std::string&) { + const std::scoped_lock lock(mut); + ++log_count; + cv.notify_all(); + }); + + // Throw in a local SDK log for good measure + LK_LOG_INFO("Should not log"); + + // Same Rust-side stimuli as RustLogsAreForwarded, but the C++ logger should filter them all. + ASSERT_TRUE(FfiClient::instance().initialize(true)); + sendFailedConnectRequest(); + ASSERT_THROW(sendInvalidFfiRequest(), std::runtime_error); + { + const FfiHandle invalid_handle(12345); + (void)invalid_handle; + } + + { + std::unique_lock lock(mut); + // Until Rust FFI supports log flushing, we need a timeout like this to ensure no logs are + // forwarded within the 1Hz threshold + EXPECT_FALSE(cv.wait_for(lock, std::chrono::seconds(2), [&] { return log_count > 0; })); + EXPECT_EQ(log_count, 0u); + } + + FfiClient::instance().shutdown(); +} + } // namespace livekit::test From 21c250a5276a0e4093f70c168e52bf0c5779ed5c Mon Sep 17 00:00:00 2001 From: Alan George Date: Tue, 19 May 2026 11:33:35 -0700 Subject: [PATCH 17/18] Try cleaning up global header inclusion --- include/livekit/livekit.h | 21 --------------------- 1 file changed, 21 deletions(-) diff --git a/include/livekit/livekit.h b/include/livekit/livekit.h index a60b4a25..ba096474 100644 --- a/include/livekit/livekit.h +++ b/include/livekit/livekit.h @@ -16,28 +16,7 @@ #pragma once -#include "livekit/audio_frame.h" -#include "livekit/audio_processing_module.h" -#include "livekit/audio_source.h" -#include "livekit/audio_stream.h" -#include "livekit/build.h" -#include "livekit/e2ee.h" -#include "livekit/local_audio_track.h" -#include "livekit/local_participant.h" -#include "livekit/local_track_publication.h" -#include "livekit/local_video_track.h" #include "livekit/logging.h" -#include "livekit/participant.h" -#include "livekit/remote_participant.h" -#include "livekit/remote_track_publication.h" -#include "livekit/room.h" -#include "livekit/room_delegate.h" -#include "livekit/room_event_types.h" -#include "livekit/tracing.h" -#include "livekit/track_publication.h" -#include "livekit/video_frame.h" -#include "livekit/video_source.h" -#include "livekit/video_stream.h" #include "livekit/visibility.h" namespace livekit { From 8210d0e58f25216078bfa382bf79fb030a5c24d9 Mon Sep 17 00:00:00 2001 From: Alan George Date: Tue, 19 May 2026 11:48:16 -0700 Subject: [PATCH 18/18] Undo header change --- include/livekit/livekit.h | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/include/livekit/livekit.h b/include/livekit/livekit.h index ba096474..a60b4a25 100644 --- a/include/livekit/livekit.h +++ b/include/livekit/livekit.h @@ -16,7 +16,28 @@ #pragma once +#include "livekit/audio_frame.h" +#include "livekit/audio_processing_module.h" +#include "livekit/audio_source.h" +#include "livekit/audio_stream.h" +#include "livekit/build.h" +#include "livekit/e2ee.h" +#include "livekit/local_audio_track.h" +#include "livekit/local_participant.h" +#include "livekit/local_track_publication.h" +#include "livekit/local_video_track.h" #include "livekit/logging.h" +#include "livekit/participant.h" +#include "livekit/remote_participant.h" +#include "livekit/remote_track_publication.h" +#include "livekit/room.h" +#include "livekit/room_delegate.h" +#include "livekit/room_event_types.h" +#include "livekit/tracing.h" +#include "livekit/track_publication.h" +#include "livekit/video_frame.h" +#include "livekit/video_source.h" +#include "livekit/video_stream.h" #include "livekit/visibility.h" namespace livekit {