Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
102 changes: 94 additions & 8 deletions src/sentry_logs.c
Original file line number Diff line number Diff line change
Expand Up @@ -13,11 +13,30 @@

#ifdef SENTRY_UNITTEST
# define QUEUE_LENGTH 5
# ifdef SENTRY_PLATFORM_WINDOWS
# include <windows.h>
# define sleep_ms(MILLISECONDS) Sleep(MILLISECONDS)
# else
# include <unistd.h>
# 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
Expand All @@ -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 = {
Expand All @@ -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.
Expand Down Expand Up @@ -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);
Comment thread
vaind marked this conversation as resolved.
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;
}

Expand Down Expand Up @@ -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;
}

Expand Down Expand Up @@ -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);
Expand All @@ -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);
}
}

Expand All @@ -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
Expand All @@ -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
6 changes: 6 additions & 0 deletions src/sentry_logs.h
Original file line number Diff line number Diff line change
Expand Up @@ -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
28 changes: 28 additions & 0 deletions src/sentry_sync.h
Original file line number Diff line number Diff line change
Expand Up @@ -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
Comment thread
vaind marked this conversation as resolved.
}

struct sentry_bgworker_s;
Comment thread
vaind marked this conversation as resolved.
typedef struct sentry_bgworker_s sentry_bgworker_t;

Expand Down
16 changes: 10 additions & 6 deletions tests/unit/test_logs.c
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
Expand All @@ -42,16 +46,15 @@ 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");
sentry_log_debug("Debug message");
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();
Expand Down Expand Up @@ -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);
Expand Down
Loading