From e229b07528bee6d9cc02a5e47d5c6b470be48f23 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Mon, 29 Sep 2025 21:08:06 +0200 Subject: [PATCH 1/5] fix(logs): Fix test failures when session tracking is enabled MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This commit fixes 3 test failures in test_logs.c that occur when auto-session tracking is enabled (the default): - basic_logging_functionality - formatted_log_messages - logs_disabled_by_default Root causes and fixes: 1. validate_logs_envelope counted all envelopes but only validated logs - Session envelopes from sentry_close() were triggering assertions - Fixed by filtering: only count/validate log envelopes, skip others 2. formatted_log_messages didn't wait for batching thread to start - Added sleep_ms(20) after sentry_init() to match other tests 3. batching_stop flag wasn't reset between sentry_init() calls - Once set to 1 during shutdown, subsequent startups would fail - Fixed by resetting to 0 in sentry__logs_startup() These issues were discovered in console SDK testing where session tracking is enabled by default and tests run sequentially in a single process. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude --- src/sentry_logs.c | 3 +++ tests/unit/test_logs.c | 12 +++++++++--- 2 files changed, 12 insertions(+), 3 deletions(-) diff --git a/src/sentry_logs.c b/src/sentry_logs.c index f4c09dfba9..df784c428b 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -733,6 +733,9 @@ sentry_log_fatal(const char *message, ...) void sentry__logs_startup(void) { + // Reset batching_stop flag in case logs system was previously shutdown + sentry__atomic_store(&g_logs_state.batching_stop, 0); + sentry__cond_init(&g_logs_state.request_flush); sentry__thread_init(&g_logs_state.batching_thread); diff --git a/tests/unit/test_logs.c b/tests/unit/test_logs.c index 9e2d89dbcb..7ff66916d1 100644 --- a/tests/unit/test_logs.c +++ b/tests/unit/test_logs.c @@ -15,15 +15,19 @@ static void validate_logs_envelope(sentry_envelope_t *envelope, void *data) { uint64_t *called = data; - *called += 1; // Verify we have at least one envelope item TEST_CHECK(sentry__envelope_get_item_count(envelope) > 0); - // Get the first item and check it's a logs item + // Get the first item and check its type const sentry_envelope_item_t *item = sentry__envelope_get_item(envelope, 0); sentry_value_t type_header = sentry__envelope_item_get_header(item, "type"); - TEST_CHECK_STRING_EQUAL(sentry_value_as_string(type_header), "log"); + const char *type = sentry_value_as_string(type_header); + + // Only validate and count log envelopes, skip others (e.g., session) + if (strcmp(type, "log") == 0) { + *called += 1; + } sentry_envelope_free(envelope); } @@ -98,6 +102,8 @@ SENTRY_TEST(formatted_log_messages) sentry_options_set_transport(options, transport); sentry_init(options); + // Allow log timer_task to start + sleep_ms(20); // Test format specifiers sentry_log_info("String: %s, Integer: %d, Float: %.2f", "test", 42, 3.14); From ebe04532e879da0e9a66ab32288faba2c4fb76ae Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Tue, 30 Sep 2025 10:27:56 +0200 Subject: [PATCH 2/5] fix(logs): Eliminate thread startup race with enum state machine MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This commit eliminates the thread startup race condition by: 1. Replacing batching_stop with enum-based thread_state - SENTRY_LOGS_THREAD_STOPPED (0): Not running - SENTRY_LOGS_THREAD_RUNNING (1): Thread active and processing logs - Improves code clarity and makes thread lifecycle explicit 2. Thread signals RUNNING state after initialization - Batching thread sets state to RUNNING after mutex setup - Provides deterministic indication that thread is ready 3. Adding test-only helper: sentry__logs_wait_for_thread_startup() - Polls thread_state until RUNNING (max 1 second) - Zero production overhead (only compiled with SENTRY_UNITTEST) - Tests explicitly wait for thread readiness instead of arbitrary sleeps 4. Updating shutdown to use atomic state transition - Atomically transitions from RUNNING to STOPPED - Detects double shutdown or never-started cases - Returns early if thread wasn't running Benefits: - Eliminates race where logs could be enqueued before thread starts - Tests are deterministic (no arbitrary timing assumptions) - Code is clearer with explicit state names - No production overhead (test helper is ifdef'd out) The one remaining sleep in basic_logging_functionality test is intentional - it tests batch timing behavior (wait for buffer flush). 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude --- src/sentry_logs.c | 78 ++++++++++++++++++++++++++++++++++++------ src/sentry_logs.h | 6 ++++ tests/unit/test_logs.c | 8 ++--- 3 files changed, 77 insertions(+), 15 deletions(-) diff --git a/src/sentry_logs.c b/src/sentry_logs.c index df784c428b..d1d1e8975f 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -13,11 +13,28 @@ #ifdef SENTRY_UNITTEST # define QUEUE_LENGTH 5 +# ifdef SENTRY_PLATFORM_WINDOWS +# include +# define sleep_ms(MILLISECONDS) Sleep(MILLISECONDS) +# else +# include +# define sleep_ms(MILLISECONDS) usleep(MILLISECONDS * 1000) +# endif #else # define QUEUE_LENGTH 100 #endif #define FLUSH_TIMER 5 +/** + * Thread lifecycle states for the logs batching thread. + */ +typedef enum { + /** Thread is not running (initial state or after shutdown) */ + SENTRY_LOGS_THREAD_STOPPED = 0, + /** Thread is running and processing logs */ + SENTRY_LOGS_THREAD_RUNNING = 1, +} sentry_logs_thread_state_t; + typedef struct { sentry_value_t logs[QUEUE_LENGTH]; long index; // (atomic) index for producer threads to get a unique slot @@ -29,7 +46,7 @@ static struct { log_buffer_t buffers[2]; // double buffer long active_idx; // (atomic) index to the active buffer long flushing; // (atomic) reentrancy guard to the flusher - long batching_stop; // (atomic) run variable of the batching thread + long thread_state; // (atomic) sentry_logs_thread_state_t sentry_cond_t request_flush; // condition variable to schedule a flush sentry_threadid_t batching_thread; // the batching thread } g_logs_state = { @@ -47,6 +64,7 @@ static struct { }, .active_idx = 0, .flushing = 0, + .thread_state = SENTRY_LOGS_THREAD_STOPPED, }; // checks whether the currently active buffer should be flushed. @@ -209,14 +227,20 @@ batching_thread_func(void *data) sentry__mutex_init(&task_lock); sentry__mutex_lock(&task_lock); - // check if thread got a shut-down signal - while (sentry__atomic_fetch(&g_logs_state.batching_stop) == 0) { + // Signal that thread is now running + sentry__atomic_store( + &g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_RUNNING); + + // Main loop: run while state is RUNNING + while (sentry__atomic_fetch(&g_logs_state.thread_state) + == SENTRY_LOGS_THREAD_RUNNING) { // Sleep for 5 seconds or until request_flush hits const int triggered_by = sentry__cond_wait_timeout( &g_logs_state.request_flush, &task_lock, 5000); - // make sure loop invariant still holds - if (sentry__atomic_fetch(&g_logs_state.batching_stop) != 0) { + // Check if we should still be running + if (sentry__atomic_fetch(&g_logs_state.thread_state) + != SENTRY_LOGS_THREAD_RUNNING) { break; } @@ -251,6 +275,7 @@ batching_thread_func(void *data) sentry__mutex_unlock(&task_lock); sentry__mutex_free(&task_lock); + SENTRY_DEBUG("batching thread exiting"); return 0; } @@ -733,8 +758,9 @@ sentry_log_fatal(const char *message, ...) void sentry__logs_startup(void) { - // Reset batching_stop flag in case logs system was previously shutdown - sentry__atomic_store(&g_logs_state.batching_stop, 0); + // Reset to stopped state in case logs system was previously shutdown + sentry__atomic_store( + &g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_STOPPED); sentry__cond_init(&g_logs_state.request_flush); @@ -753,11 +779,16 @@ sentry__logs_shutdown(uint64_t timeout) (void)timeout; SENTRY_DEBUG("shutting down logs system"); - // Signal the batching thread to stop running - if (sentry__atomic_store(&g_logs_state.batching_stop, 1) != 0) { - SENTRY_DEBUG("preventing double shutdown of logs system"); + // Atomically transition from RUNNING to STOPPED + const long old_state = sentry__atomic_store( + &g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_STOPPED); + + if (old_state == SENTRY_LOGS_THREAD_STOPPED) { + SENTRY_DEBUG("logs thread not running, skipping shutdown"); return; } + + // Thread was running, signal it to stop sentry__cond_wake(&g_logs_state.request_flush); sentry__thread_join(g_logs_state.batching_thread); @@ -768,3 +799,30 @@ sentry__logs_shutdown(uint64_t timeout) SENTRY_DEBUG("logs system shutdown complete"); } + +#ifdef SENTRY_UNITTEST +/** + * Wait for the logs batching thread to be ready. + * This is a test-only helper to avoid race conditions in tests. + */ +void +sentry__logs_wait_for_thread_startup(void) +{ + const int max_wait_ms = 1000; + const int check_interval_ms = 10; + const int max_attempts = max_wait_ms / check_interval_ms; + + for (int i = 0; i < max_attempts; i++) { + const long state = sentry__atomic_fetch(&g_logs_state.thread_state); + if (state == SENTRY_LOGS_THREAD_RUNNING) { + SENTRY_TRACEF( + "logs thread ready after %d ms", i * check_interval_ms); + return; + } + sleep_ms(check_interval_ms); + } + + SENTRY_WARNF( + "logs thread failed to start within %d ms timeout", max_wait_ms); +} +#endif diff --git a/src/sentry_logs.h b/src/sentry_logs.h index b23e652639..ce0f390743 100644 --- a/src/sentry_logs.h +++ b/src/sentry_logs.h @@ -19,6 +19,12 @@ void sentry__logs_shutdown(uint64_t timeout); #ifdef SENTRY_UNITTEST int populate_message_parameters( sentry_value_t attributes, const char *message, va_list args); + +/** + * Wait for the logs batching thread to be ready. + * This is a test-only helper to avoid race conditions in tests. + */ +void sentry__logs_wait_for_thread_startup(void); #endif #endif diff --git a/tests/unit/test_logs.c b/tests/unit/test_logs.c index 7ff66916d1..ad773ef645 100644 --- a/tests/unit/test_logs.c +++ b/tests/unit/test_logs.c @@ -46,8 +46,7 @@ SENTRY_TEST(basic_logging_functionality) sentry_options_set_transport(options, transport); sentry_init(options); - // TODO if we don't sleep, log timer_task might not start in time to flush - sleep_ms(20); + sentry__logs_wait_for_thread_startup(); // These should not crash and should respect the enable_logs option sentry_log_trace("Trace message"); @@ -55,7 +54,7 @@ SENTRY_TEST(basic_logging_functionality) sentry_log_info("Info message"); sentry_log_warn("Warning message"); sentry_log_error("Error message"); - // sleep to finish flush of the first 5, otherwise failed enqueue + // Sleep to allow first batch to flush (testing batch timing behavior) sleep_ms(20); sentry_log_fatal("Fatal message"); sentry_close(); @@ -102,8 +101,7 @@ SENTRY_TEST(formatted_log_messages) sentry_options_set_transport(options, transport); sentry_init(options); - // Allow log timer_task to start - sleep_ms(20); + sentry__logs_wait_for_thread_startup(); // Test format specifiers sentry_log_info("String: %s, Integer: %d, Float: %.2f", "test", 42, 3.14); From b14a575823664d8f2a2fa026abf14b2e45b03205 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Tue, 30 Sep 2025 12:54:32 +0200 Subject: [PATCH 3/5] fix(logs): Fix thread lifecycle race condition causing memory leaks MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This commit fixes a race condition in the logs batching thread lifecycle that caused valgrind to report 336 byte memory leaks in CI tests. ## Problem When `sentry__logs_shutdown()` ran before the batching thread transitioned from initial state to RUNNING, the two-state model couldn't distinguish between "never started" and "starting but not yet running", causing shutdown to skip joining the thread. ## Solution 1. Added three-state lifecycle enum: - STOPPED (0): Thread never started or shut down - STARTING (1): Thread spawned but not yet initialized - RUNNING (2): Thread active and processing logs 2. Added `sentry__atomic_compare_swap()` primitive for atomic state verification (cross-platform: Windows InterlockedCompareExchange, POSIX __atomic_compare_exchange_n) 3. Startup sets state to STARTING before spawning thread 4. Thread uses CAS to verify STARTING → RUNNING transition - If CAS fails (shutdown already set to STOPPED), exits cleanly - Guarantees thread only runs if it successfully transitioned 5. Shutdown always joins thread if old state != STOPPED ## Benefits - Eliminates race condition where shutdown could miss a spawned thread - Thread explicitly verifies state transition with CAS - No memory leaks in any shutdown scenario - All 212 unit tests pass - All log integration tests pass Fixes test failures: - test_before_send_log - test_before_send_log_discard 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude --- src/sentry_logs.c | 35 ++++++++++++++++++++++++++--------- src/sentry_sync.h | 21 +++++++++++++++++++++ 2 files changed, 47 insertions(+), 9 deletions(-) diff --git a/src/sentry_logs.c b/src/sentry_logs.c index d1d1e8975f..a4d8eb7bb9 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -31,8 +31,10 @@ typedef enum { /** Thread is not running (initial state or after shutdown) */ SENTRY_LOGS_THREAD_STOPPED = 0, + /** Thread is starting up but not yet ready */ + SENTRY_LOGS_THREAD_STARTING = 1, /** Thread is running and processing logs */ - SENTRY_LOGS_THREAD_RUNNING = 1, + SENTRY_LOGS_THREAD_RUNNING = 2, } sentry_logs_thread_state_t; typedef struct { @@ -227,9 +229,16 @@ batching_thread_func(void *data) sentry__mutex_init(&task_lock); sentry__mutex_lock(&task_lock); - // Signal that thread is now running - sentry__atomic_store( - &g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_RUNNING); + // Transition from STARTING to RUNNING + // If CAS fails, shutdown already set state to STOPPED, so exit immediately + if (!sentry__atomic_compare_swap(&g_logs_state.thread_state, + (long)SENTRY_LOGS_THREAD_STARTING, + (long)SENTRY_LOGS_THREAD_RUNNING)) { + SENTRY_DEBUG("logs thread detected shutdown during startup, exiting"); + sentry__mutex_unlock(&task_lock); + sentry__mutex_free(&task_lock); + return 0; + } // Main loop: run while state is RUNNING while (sentry__atomic_fetch(&g_logs_state.thread_state) @@ -758,9 +767,11 @@ sentry_log_fatal(const char *message, ...) void sentry__logs_startup(void) { - // Reset to stopped state in case logs system was previously shutdown + // Mark thread as starting before actually spawning so thread can transition + // to RUNNING. This prevents shutdown from thinking the thread was never + // started if it races with the thread's initialization. sentry__atomic_store( - &g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_STOPPED); + &g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_STARTING); sentry__cond_init(&g_logs_state.request_flush); @@ -770,6 +781,9 @@ sentry__logs_startup(void) if (spawn_result == 1) { SENTRY_ERROR("Failed to start batching thread"); + // Failed to spawn, reset to STOPPED + sentry__atomic_store( + &g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_STOPPED); } } @@ -779,17 +793,20 @@ sentry__logs_shutdown(uint64_t timeout) (void)timeout; SENTRY_DEBUG("shutting down logs system"); - // Atomically transition from RUNNING to STOPPED + // Atomically transition to STOPPED and get the previous state const long old_state = sentry__atomic_store( &g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_STOPPED); + // If thread was never started, nothing to do if (old_state == SENTRY_LOGS_THREAD_STOPPED) { - SENTRY_DEBUG("logs thread not running, skipping shutdown"); + SENTRY_DEBUG("logs thread was not started, skipping shutdown"); return; } - // Thread was running, signal it to stop + // Thread was started (either STARTING or RUNNING), signal it to stop sentry__cond_wake(&g_logs_state.request_flush); + + // Always join the thread to avoid leaks sentry__thread_join(g_logs_state.batching_thread); // Perform final flush to ensure any remaining logs are sent diff --git a/src/sentry_sync.h b/src/sentry_sync.h index dfbe59e14e..7fc61c1049 100644 --- a/src/sentry_sync.h +++ b/src/sentry_sync.h @@ -384,6 +384,27 @@ sentry__atomic_fetch(volatile long *val) return sentry__atomic_fetch_and_add(val, 0); } +/** + * Compare and swap: atomically compare *val with expected, and if equal, + * set *val to desired. Returns true if the swap occurred. + */ +static inline bool +sentry__atomic_compare_swap(volatile long *val, long expected, long desired) +{ +#ifdef SENTRY_PLATFORM_WINDOWS +# if SIZEOF_LONG == 8 + return InterlockedCompareExchange64((LONG64 *)val, desired, expected) + == expected; +# else + return InterlockedCompareExchange((LONG *)val, desired, expected) + == expected; +# endif +#else + return __atomic_compare_exchange_n( + val, &expected, desired, false, __ATOMIC_SEQ_CST, __ATOMIC_SEQ_CST); +#endif +} + struct sentry_bgworker_s; typedef struct sentry_bgworker_s sentry_bgworker_t; From f8b33d31385f391e3b5b34b6076298c3ce9107c9 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos Date: Tue, 30 Sep 2025 13:51:13 +0200 Subject: [PATCH 4/5] docs(logs): Address code review comments with clarifying documentation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Addresses bot review feedback by adding documentation without changing behavior: 1. **CAS memory ordering**: Added comment explaining sequential consistency usage for thread state transitions and why it's appropriate for synchronization 2. **Condition variable cleanup**: Added note explaining that static storage condition variables don't require explicit cleanup on POSIX and Windows 3. **CAS function documentation**: Enhanced docstring to document memory ordering guarantees and note that ABA problem isn't a concern for simple integer state machines 4. **Shutdown race handling**: Added comment explaining how the atomic CAS in the thread prevents the race when shutdown occurs during STARTING state All changes are documentation/comments only - no behavior changes. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude --- src/sentry_logs.c | 10 +++++++++- src/sentry_sync.h | 7 +++++++ 2 files changed, 16 insertions(+), 1 deletion(-) diff --git a/src/sentry_logs.c b/src/sentry_logs.c index a4d8eb7bb9..2020093fb4 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -229,8 +229,11 @@ batching_thread_func(void *data) sentry__mutex_init(&task_lock); sentry__mutex_lock(&task_lock); - // Transition from STARTING to RUNNING + // Transition from STARTING to RUNNING using compare-and-swap + // CAS ensures atomic state verification: only succeeds if state is STARTING // If CAS fails, shutdown already set state to STOPPED, so exit immediately + // Uses sequential consistency to ensure all thread initialization is + // visible if (!sentry__atomic_compare_swap(&g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_STARTING, (long)SENTRY_LOGS_THREAD_RUNNING)) { @@ -782,6 +785,8 @@ sentry__logs_startup(void) if (spawn_result == 1) { SENTRY_ERROR("Failed to start batching thread"); // Failed to spawn, reset to STOPPED + // Note: condition variable doesn't need explicit cleanup for static + // storage (pthread_cond_t on POSIX and CONDITION_VARIABLE on Windows) sentry__atomic_store( &g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_STOPPED); } @@ -794,6 +799,9 @@ sentry__logs_shutdown(uint64_t timeout) SENTRY_DEBUG("shutting down logs system"); // Atomically transition to STOPPED and get the previous state + // This handles the race where thread might be in STARTING state: + // - If thread's CAS hasn't run yet: CAS will fail, thread exits cleanly + // - If thread already transitioned to RUNNING: normal shutdown path const long old_state = sentry__atomic_store( &g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_STOPPED); diff --git a/src/sentry_sync.h b/src/sentry_sync.h index 7fc61c1049..c199744347 100644 --- a/src/sentry_sync.h +++ b/src/sentry_sync.h @@ -387,6 +387,13 @@ sentry__atomic_fetch(volatile long *val) /** * Compare and swap: atomically compare *val with expected, and if equal, * set *val to desired. Returns true if the swap occurred. + * + * Uses sequential consistency (ATOMIC_SEQ_CST / InterlockedCompareExchange) + * to ensure all memory operations are visible across threads. This is + * appropriate for thread synchronization and state machine transitions. + * + * Note: The ABA problem (where a value changes A->B->A between reads) is not + * a concern for simple integer-based state machines with monotonic transitions. */ static inline bool sentry__atomic_compare_swap(volatile long *val, long expected, long desired) From f0f2f05ef96f5ee664f0ffce2e9742901fccc6f3 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos <6349682+vaind@users.noreply.github.com> Date: Tue, 30 Sep 2025 15:13:42 +0200 Subject: [PATCH 5/5] Update src/sentry_logs.c Co-authored-by: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> --- src/sentry_logs.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/sentry_logs.c b/src/sentry_logs.c index 2020093fb4..4cd17128c1 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -840,7 +840,7 @@ sentry__logs_wait_for_thread_startup(void) for (int i = 0; i < max_attempts; i++) { const long state = sentry__atomic_fetch(&g_logs_state.thread_state); if (state == SENTRY_LOGS_THREAD_RUNNING) { - SENTRY_TRACEF( + SENTRY_DEBUGF( "logs thread ready after %d ms", i * check_interval_ms); return; }