diff --git a/src/sentry_logs.c b/src/sentry_logs.c index f4c09dfba9..4cd17128c1 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -13,11 +13,30 @@ #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 starting up but not yet ready */ + SENTRY_LOGS_THREAD_STARTING = 1, + /** Thread is running and processing logs */ + SENTRY_LOGS_THREAD_RUNNING = 2, +} 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 +48,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 +66,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 +229,30 @@ 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) { + // 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)) { + 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) + == 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 +287,7 @@ batching_thread_func(void *data) sentry__mutex_unlock(&task_lock); sentry__mutex_free(&task_lock); + SENTRY_DEBUG("batching thread exiting"); return 0; } @@ -733,6 +770,12 @@ sentry_log_fatal(const char *message, ...) void sentry__logs_startup(void) { + // 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_STARTING); + sentry__cond_init(&g_logs_state.request_flush); sentry__thread_init(&g_logs_state.batching_thread); @@ -741,6 +784,11 @@ 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); } } @@ -750,12 +798,23 @@ 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 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); + + // If thread was never started, nothing to do + if (old_state == SENTRY_LOGS_THREAD_STOPPED) { + SENTRY_DEBUG("logs thread was not started, skipping shutdown"); return; } + + // 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 @@ -765,3 +824,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_DEBUGF( + "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/src/sentry_sync.h b/src/sentry_sync.h index dfbe59e14e..c199744347 100644 --- a/src/sentry_sync.h +++ b/src/sentry_sync.h @@ -384,6 +384,34 @@ 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. + * + * 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) +{ +#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; diff --git a/tests/unit/test_logs.c b/tests/unit/test_logs.c index 9e2d89dbcb..ad773ef645 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); } @@ -42,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"); @@ -51,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(); @@ -98,6 +101,7 @@ SENTRY_TEST(formatted_log_messages) sentry_options_set_transport(options, transport); sentry_init(options); + sentry__logs_wait_for_thread_startup(); // Test format specifiers sentry_log_info("String: %s, Integer: %d, Float: %.2f", "test", 42, 3.14);