diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 95242f17c..25f567067 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -150,7 +150,8 @@ jobs: os: windows-latest TEST_MINGW: 1 MINGW_PKG_PREFIX: x86_64-w64-mingw32 - MINGW_ASM_MASM_COMPILER: llvm-ml;-m64 + MINGW_ASM_MASM_COMPILER: llvm-ml + MINGW_ASM_MASM_FLAGS: -m64 # The Android emulator is currently only available on macos, see: # https://docs.microsoft.com/en-us/azure/devops/pipelines/ecosystems/android?view=azure-devops#test-on-the-android-emulator # TODO: switch to reactivecircus/android-emulator-runner, concurrently running emulators continuously fail now. @@ -244,12 +245,32 @@ jobs: if: ${{ runner.os == 'macOS' && matrix.os == 'macos-15-large' && matrix.RUN_ANALYZER == 'asan,llvm-cov' }} run: echo $(brew --prefix llvm@18)/bin >> $GITHUB_PATH + - name: Set macOS SDKROOT + if: ${{ runner.os == 'macOS' }} + run: echo "SDKROOT=macosx" >> "$GITHUB_ENV" + + - name: Remove Strawberry Perl from PATH + if: ${{ runner.os == 'Windows' }} + shell: powershell + run: | + $strawberryBins = @( + 'C:\Strawberry\c\bin', + 'C:\Strawberry\perl\site\bin', + 'C:\Strawberry\perl\bin' + ) + + $cleanedPaths = $env:Path -split ';' | Where-Object { $_ -and ($strawberryBins -notcontains $_) } + $newPath = ($cleanedPaths -join ';') + + "PATH=$newPath" | Out-File -FilePath $env:GITHUB_ENV -Encoding utf8 -Append + - name: Installing LLVM-MINGW Dependencies if: ${{ runner.os == 'Windows' && env['TEST_MINGW'] }} shell: powershell env: MINGW_PKG_PREFIX: ${{ matrix.MINGW_PKG_PREFIX }} MINGW_ASM_MASM_COMPILER: ${{ matrix.MINGW_ASM_MASM_COMPILER }} + MINGW_ASM_MASM_FLAGS: ${{ matrix.MINGW_ASM_MASM_FLAGS }} run: . "scripts\install-llvm-mingw.ps1" - name: Set up zlib for Windows diff --git a/examples/example.c b/examples/example.c index 68ed11f9c..e4ba4c694 100644 --- a/examples/example.c +++ b/examples/example.c @@ -24,6 +24,7 @@ # define sleep_s(SECONDS) Sleep((SECONDS) * 1000) #else +# include # include # include @@ -58,6 +59,8 @@ get_current_thread_id() } #endif +#define NUM_THREADS 50 + static double traces_sampler_callback(const sentry_transaction_context_t *transaction_ctx, sentry_value_t custom_sampling_ctx, const int *parent_sampled) @@ -155,6 +158,33 @@ discarding_before_transaction_callback(sentry_value_t tx, void *user_data) return tx; } +static sentry_value_t +before_send_log_callback(sentry_value_t log, void *user_data) +{ + (void)user_data; + sentry_value_t attribute = sentry_value_new_object(); + sentry_value_set_by_key( + attribute, "value", sentry_value_new_string("little")); + sentry_value_set_by_key( + attribute, "type", sentry_value_new_string("string")); + sentry_value_set_by_key(sentry_value_get_by_key(log, "attributes"), + "coffeepot.size", attribute); + return log; +} + +static sentry_value_t +discarding_before_send_log_callback(sentry_value_t log, void *user_data) +{ + (void)user_data; + if (sentry_value_is_null( + sentry_value_get_by_key(sentry_value_get_by_key(log, "attributes"), + "sentry.message.template"))) { + sentry_value_decref(log); + return sentry_value_new_null(); + } + return log; +} + static void print_envelope(sentry_envelope_t *envelope, void *unused_state) { @@ -272,6 +302,32 @@ create_debug_crumb(const char *message) return debug_crumb; } +#ifdef SENTRY_PLATFORM_WINDOWS +DWORD WINAPI +log_thread_func(LPVOID lpParam) +{ + (void)lpParam; + int LOG_COUNT = 100; + for (int i = 0; i < LOG_COUNT; i++) { + sentry_log_debug( + "thread log %d on thread %lu", i, get_current_thread_id()); + } + return 0; +} +#else +void * +log_thread_func(void *arg) +{ + (void)arg; + int LOG_COUNT = 100; + for (int i = 0; i < LOG_COUNT; i++) { + sentry_log_debug( + "thread log %d on thread %llu", i, get_current_thread_id()); + } + return NULL; +} +#endif + int main(int argc, char **argv) { @@ -345,6 +401,16 @@ main(int argc, char **argv) options, discarding_before_transaction_callback, NULL); } + if (has_arg(argc, argv, "before-send-log")) { + sentry_options_set_before_send_log( + options, before_send_log_callback, NULL); + } + + if (has_arg(argc, argv, "discarding-before-send-log")) { + sentry_options_set_before_send_log( + options, discarding_before_send_log_callback, NULL); + } + if (has_arg(argc, argv, "traces-sampler")) { sentry_options_set_traces_sampler(options, traces_sampler_callback); } @@ -385,7 +451,9 @@ main(int argc, char **argv) sentry_options_set_enable_logs(options, true); } - sentry_init(options); + if (0 != sentry_init(options)) { + return EXIT_FAILURE; + } if (has_arg(argc, argv, "attachment")) { sentry_attachment_t *bytes @@ -395,28 +463,42 @@ main(int argc, char **argv) // TODO incorporate into test if (sentry_options_get_enable_logs(options)) { - sentry_log_warn( - "This is a big number %" PRIu64, 18446744073709551615ULL); - sentry_log_warn("This is a medium number as unsigned %" PRIu64, - 9007199254740991ULL); - sentry_log_warn( - "This is a medium number as signed %" PRId64, 9007199254740991LL); - sentry_log_trace("We log it up %i%%, %s style", 100, "trace"); - sentry_log_debug("We log it up %i%%, %s style", 100, "debug"); - sentry_log_info("We log it up %i%%, %s style", 100, "info"); - sentry_log_warn("We log it up %i%%, %s style", 100, "warn"); - sentry_log_error("We log it up %i%%, %s style", 100, "error"); - sentry_log_fatal("We log it up %i%%, %s style", 100, "fatal"); - - // Test the logger with various parameter types - sentry_log_info( - "API call to %s completed in %d ms with %f success rate", - "/api/products", 2500, 0.95); - - sentry_log_warn("Processing %d items, found %u errors, pointer: %p", - 100, 5u, (void *)0x12345678); - - sentry_log_error("Character '%c' is invalid", 'X'); + if (has_arg(argc, argv, "capture-log")) { + sentry_log_debug("I'm a log message!"); + } + if (has_arg(argc, argv, "logs-timer")) { + for (int i = 0; i < 10; i++) { + sentry_log_info("Informational log nr.%d", i); + } + // sleep >5s to trigger logs timer + sleep_s(6); + // we should see two envelopes make its way to Sentry + sentry_log_debug("post-sleep log"); + } + if (has_arg(argc, argv, "logs-threads")) { + // Spawn multiple threads to test concurrent logging +#ifdef SENTRY_PLATFORM_WINDOWS + HANDLE threads[NUM_THREADS]; + for (int t = 0; t < NUM_THREADS; t++) { + threads[t] + = CreateThread(NULL, 0, log_thread_func, NULL, 0, NULL); + } + + WaitForMultipleObjects(NUM_THREADS, threads, TRUE, INFINITE); + + for (int t = 0; t < NUM_THREADS; t++) { + CloseHandle(threads[t]); + } +#else + pthread_t threads[NUM_THREADS]; + for (int t = 0; t < NUM_THREADS; t++) { + pthread_create(&threads[t], NULL, log_thread_func, NULL); + } + for (int t = 0; t < NUM_THREADS; t++) { + pthread_join(threads[t], NULL); + } +#endif + } } if (!has_arg(argc, argv, "no-setup")) { @@ -681,4 +763,6 @@ main(int argc, char **argv) if (has_arg(argc, argv, "crash-after-shutdown")) { trigger_crash(); } + + return EXIT_SUCCESS; } diff --git a/include/sentry.h b/include/sentry.h index d642fd133..292235c49 100644 --- a/include/sentry.h +++ b/include/sentry.h @@ -1876,12 +1876,41 @@ SENTRY_EXPERIMENTAL_API void sentry_options_set_enable_logs( SENTRY_EXPERIMENTAL_API int sentry_options_get_enable_logs( const sentry_options_t *opts); -SENTRY_EXPERIMENTAL_API void sentry_log_trace(const char *message, ...); -SENTRY_EXPERIMENTAL_API void sentry_log_debug(const char *message, ...); -SENTRY_EXPERIMENTAL_API void sentry_log_info(const char *message, ...); -SENTRY_EXPERIMENTAL_API void sentry_log_warn(const char *message, ...); -SENTRY_EXPERIMENTAL_API void sentry_log_error(const char *message, ...); -SENTRY_EXPERIMENTAL_API void sentry_log_fatal(const char *message, ...); +typedef enum { + SENTRY_LOG_RETURN_SUCCESS = 0, + SENTRY_LOG_RETURN_DISCARD = 1, + SENTRY_LOG_RETURN_FAILED = 2, + SENTRY_LOG_RETURN_DISABLED = 3 +} log_return_value_t; +SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_trace( + const char *message, ...); +SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_debug( + const char *message, ...); +SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_info( + const char *message, ...); +SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_warn( + const char *message, ...); +SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_error( + const char *message, ...); +SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_fatal( + const char *message, ...); + +/** + * Type of the `before_send_log` callback. + * + * The callback takes ownership of the `log`, and should usually return + * that same log. In case the log should be discarded, the + * callback needs to call `sentry_value_decref` on the provided log, and + * return a `sentry_value_new_null()` instead. + */ +typedef sentry_value_t (*sentry_before_send_log_function_t)( + sentry_value_t log, void *user_data); + +/** + * Sets the `before_send_log` callback. + */ +SENTRY_EXPERIMENTAL_API void sentry_options_set_before_send_log( + sentry_options_t *opts, sentry_before_send_log_function_t func, void *data); #ifdef SENTRY_PLATFORM_LINUX diff --git a/scripts/install-llvm-mingw.ps1 b/scripts/install-llvm-mingw.ps1 index 3e6d40e08..470e207ef 100755 --- a/scripts/install-llvm-mingw.ps1 +++ b/scripts/install-llvm-mingw.ps1 @@ -55,4 +55,19 @@ Expand-Archive -LiteralPath "${NINJA_DL_PATH}" -DestinationPath "${NINJA_INSTALL "PATH=${NINJA_INSTALL_PATH}; $env:PATH" | Out-File -FilePath $env:GITHUB_ENV -Encoding utf8 -Append # export CMAKE_DEFINES to the runner environment -"CMAKE_DEFINES=${env:CMAKE_DEFINES} -DCMAKE_C_COMPILER=${env:MINGW_PKG_PREFIX}-gcc -DCMAKE_CXX_COMPILER=${env:MINGW_PKG_PREFIX}-g++ -DCMAKE_RC_COMPILER=${env:MINGW_PKG_PREFIX}-windres -DCMAKE_ASM_MASM_COMPILER=${env:MINGW_ASM_MASM_COMPILER}" | Out-File -FilePath $env:GITHUB_ENV -Encoding utf8 -Append \ No newline at end of file +$cmakeDefines = @() + +if ($env:CMAKE_DEFINES) { + $cmakeDefines += $env:CMAKE_DEFINES +} + +$cmakeDefines += @( + "-DCMAKE_C_COMPILER=$($env:MINGW_PKG_PREFIX)-gcc" + "-DCMAKE_CXX_COMPILER=$($env:MINGW_PKG_PREFIX)-g++" + "-DCMAKE_RC_COMPILER=$($env:MINGW_PKG_PREFIX)-windres" + "-DCMAKE_ASM_MASM_COMPILER:FILEPATH=$($LLVM_MINGW_INSTALL_PATH -replace '\\','/')/bin/$($env:MINGW_ASM_MASM_COMPILER).exe" + "-DCMAKE_ASM_MASM_FLAGS=$env:MINGW_ASM_MASM_FLAGS" +) + +"CMAKE_DEFINES=$($cmakeDefines -join ' ')" | Out-File -FilePath $env:GITHUB_ENV -Encoding utf8 -Append + diff --git a/src/sentry_core.c b/src/sentry_core.c index 12c7f88f7..3b07c6c09 100644 --- a/src/sentry_core.c +++ b/src/sentry_core.c @@ -8,6 +8,7 @@ #include "sentry_core.h" #include "sentry_database.h" #include "sentry_envelope.h" +#include "sentry_logs.h" #include "sentry_options.h" #include "sentry_os.h" #include "sentry_path.h" @@ -284,6 +285,10 @@ sentry_init(sentry_options_t *options) sentry_start_session(); } + if (options->enable_logs) { + sentry__logs_startup(); + } + sentry__mutex_unlock(&g_options_lock); return 0; @@ -310,6 +315,16 @@ sentry_flush(uint64_t timeout) int sentry_close(void) { + // Shutdown logs system before locking options to ensure logs are flushed + // TODO is this the only way? we got a potential deadlock on the options + // otherwise + // (for envelope creation, see sentry__envelope_new) + SENTRY_WITH_OPTIONS (options) { + if (options->enable_logs) { + sentry__logs_shutdown(options->shutdown_timeout); + } + } + SENTRY__MUTEX_INIT_DYN_ONCE(g_options_lock); // this function is to be called only once, so we do not allow more than one // caller diff --git a/src/sentry_envelope.c b/src/sentry_envelope.c index 9cf3305fe..e19272d4a 100644 --- a/src/sentry_envelope.c +++ b/src/sentry_envelope.c @@ -420,9 +420,12 @@ sentry__envelope_add_logs(sentry_envelope_t *envelope, sentry_value_t logs) sentry__envelope_item_set_header( item, "type", sentry_value_new_string("log")); sentry__envelope_item_set_header(item, "item_count", - sentry_value_new_int32((int32_t)sentry_value_get_length(logs))); + sentry_value_new_int32((int32_t)sentry_value_get_length( + sentry_value_get_by_key(logs, "items")))); sentry__envelope_item_set_header(item, "content_type", sentry_value_new_string("application/vnd.sentry.items.log+json")); + sentry_value_t length = sentry_value_new_int32((int32_t)item->payload_len); + sentry__envelope_item_set_header(item, "length", length); return item; } diff --git a/src/sentry_logs.c b/src/sentry_logs.c index 319be0717..c2b7908d1 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -4,10 +4,256 @@ #include "sentry_options.h" #include "sentry_os.h" #include "sentry_scope.h" - +#include "sentry_sync.h" +#if defined(SENTRY_PLATFORM_UNIX) || defined(SENTRY_PLATFORM_NX) +# include "sentry_unix_spinlock.h" +#endif #include #include +// TODO think about this +#ifdef SENTRY_UNITTEST +# define QUEUE_LENGTH 5 +#else +# define QUEUE_LENGTH 100 +#endif +#define FLUSH_TIMER 5 + +typedef struct { + sentry_value_t logs[QUEUE_LENGTH]; + long index; // (atomic) index for producer threads to get a unique slot + long adding; // (atomic) count of in-flight writers on this buffer + long sealed; // (atomic) 0=writeable, 1=sealed (meaning we drop) +} log_buffer_t; + +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 + sentry_cond_t request_flush; // condition variable to schedule a flush + sentry_threadid_t batching_thread; // the batching thread +} g_logs_state = { + { + { + .index = 0, + .adding = 0, + .sealed = 0, + }, + { + .index = 0, + .adding = 0, + .sealed = 0, + }, + }, + .active_idx = 0, + .flushing = 0, +}; + +// checks whether the currently active buffer should be flushed. +// otherwise we could miss the trigger of adding the last log if we're actively +// flushing the other buffer already. +// we can safely check the state of the active buffer, as the only thread that +// can change which buffer is active is the one calling this check function +// inside flush_logs_queue() below +static bool +check_for_flush_condition(void) +{ + // In flush_logs_queue, after finishing a flush: + long current_active = sentry__atomic_fetch(&g_logs_state.active_idx); + log_buffer_t *current_buf = &g_logs_state.buffers[current_active]; + + // Check if current active buffer is also full + // We could even lower the threshold for high-contention scenarios + return sentry__atomic_fetch(¤t_buf->index) >= QUEUE_LENGTH; +} + +static void +flush_logs_queue(void) +{ + const long already_flushing + = sentry__atomic_store(&g_logs_state.flushing, 1); + if (already_flushing) { + return; + } + do { + // prep both buffers + long old_buf_idx = sentry__atomic_fetch(&g_logs_state.active_idx); + long new_buf_idx = 1 - old_buf_idx; + log_buffer_t *old_buf = &g_logs_state.buffers[old_buf_idx]; + log_buffer_t *new_buf = &g_logs_state.buffers[new_buf_idx]; + + // reset new buffer... + sentry__atomic_store(&new_buf->index, 0); + sentry__atomic_store(&new_buf->adding, 0); + sentry__atomic_store(&new_buf->sealed, 0); + + // ...and make it active (after this we're good to go producer side) + sentry__atomic_store(&g_logs_state.active_idx, new_buf_idx); + + // seal old buffer + sentry__atomic_store(&old_buf->sealed, 1); + + // Wait for all in-flight producers of the old buffer + while (sentry__atomic_fetch(&old_buf->adding) > 0) { + // TODO currently only on unix +#ifdef SENTRY_PLATFORM_UNIX + sentry__cpu_relax(); +#endif + } + + long n = sentry__atomic_store(&old_buf->index, 0); + if (n > QUEUE_LENGTH) { + n = QUEUE_LENGTH; + } + + if (n > 0) { + // now we can do the actual batching of the old buffer + + sentry_value_t logs = sentry_value_new_object(); + sentry_value_t log_items = sentry_value_new_list(); + int i; + for (i = 0; i < n; i++) { + sentry_value_append(log_items, old_buf->logs[i]); + } + sentry_value_set_by_key(logs, "items", log_items); + + sentry_envelope_t *envelope = sentry__envelope_new(); + sentry__envelope_add_logs(envelope, logs); + SENTRY_WITH_OPTIONS (options) { + sentry__capture_envelope(options->transport, envelope); + } + sentry_value_decref(logs); + } + } while (check_for_flush_condition()); + + sentry__atomic_store(&g_logs_state.flushing, 0); +} + +#define ENQUEUE_MAX_RETRIES 2 + +static bool +enqueue_log(sentry_value_t log) +{ + for (int attempt = 0; attempt <= ENQUEUE_MAX_RETRIES; attempt++) { + // retrieve the active buffer + const long active_idx = sentry__atomic_fetch(&g_logs_state.active_idx); + log_buffer_t *active = &g_logs_state.buffers[active_idx]; + + // if the buffer is already sealed we retry or drop and exit early. + if (sentry__atomic_fetch(&active->sealed) != 0) { + if (attempt == ENQUEUE_MAX_RETRIES) { + return false; + } + continue; + } + + // `adding` is our boundary for this buffer since it keeps the flusher + // blocked. We have to recheck that the flusher hasn't already switched + // the active buffer or sealed the one this thread is on. If either is + // true we have to unblock the flusher and retry or drop the log. + sentry__atomic_fetch_and_add(&active->adding, 1); + const long active_idx_check + = sentry__atomic_fetch(&g_logs_state.active_idx); + const long sealed_check = sentry__atomic_fetch(&active->sealed); + if (active_idx != active_idx_check) { + sentry__atomic_fetch_and_add(&active->adding, -1); + if (attempt == ENQUEUE_MAX_RETRIES) { + return false; + } + continue; + } + if (sealed_check) { + sentry__atomic_fetch_and_add(&active->adding, -1); + if (attempt == ENQUEUE_MAX_RETRIES) { + return false; + } + continue; + } + + // Now we can finally request a slot and check if the log fits in this + // buffer. + const long log_idx = sentry__atomic_fetch_and_add(&active->index, 1); + if (log_idx < QUEUE_LENGTH) { + // got a slot, write log to the buffer and unblock flusher + active->logs[log_idx] = log; + sentry__atomic_fetch_and_add(&active->adding, -1); + + // Check if active buffer is now full and trigger flush. We could + // introduce additional watermarks here to trigger the flush earlier + // under high contention. + if (log_idx == QUEUE_LENGTH - 1) { + sentry__cond_wake(&g_logs_state.request_flush); + } + return true; + } + // ping the batching thread to flush, since we could miss a cond_wake + // on adding the last item + sentry__cond_wake(&g_logs_state.request_flush); + // Buffer is already full, roll back our increments and retry or drop. + sentry__atomic_fetch_and_add(&active->adding, -1); + if (attempt == ENQUEUE_MAX_RETRIES) { + // TODO report this (e.g. client reports) + return false; + } + } + return false; +} + +SENTRY_THREAD_FN +batching_thread_func(void *data) +{ + (void)data; + SENTRY_DEBUG("Starting batching thread"); + sentry_mutex_t task_lock; + 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) { + // 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) { + break; + } + + switch (triggered_by) { + case 0: +#ifdef SENTRY_PLATFORM_WINDOWS + if (GetLastError() == ERROR_TIMEOUT) { + SENTRY_DEBUG("Logs flushed by timeout"); + break; + } +#endif + SENTRY_DEBUG("Logs flushed by filled buffer"); + break; +#ifdef SENTRY_PLATFORM_UNIX + case ETIMEDOUT: + SENTRY_DEBUG("Logs flushed by timeout"); + break; +#endif +#ifdef SENTRY_PLATFORM_WINDOWS + case 1: + SENTRY_DEBUG("Logs flushed by filled buffer"); + break; +#endif + default: + SENTRY_WARN("Logs flush trigger returned unexpected value"); + continue; + } + + // Try to flush logs + flush_logs_queue(); + } + + sentry__mutex_unlock(&task_lock); + sentry__mutex_free(&task_lock); + return 0; +} + static const char * level_as_string(sentry_level_t level) { @@ -157,12 +403,13 @@ skip_length(const char *fmt_ptr) return fmt_ptr; } -static void +// returns how many parameters were added to the attributes object +static int populate_message_parameters( sentry_value_t attributes, const char *message, va_list args) { if (!message || sentry_value_is_null(attributes)) { - return; + return 0; } const char *fmt_ptr = message; @@ -204,8 +451,13 @@ populate_message_parameters( } va_end(args_copy); + return param_index; } +/** + * This function assumes that `value` is owned, so we have to make sure that the + * `value` was created or cloned by the caller or even better inc_refed. + */ static void add_attribute(sentry_value_t attributes, sentry_value_t value, const char *type, const char *name) @@ -216,56 +468,34 @@ add_attribute(sentry_value_t attributes, sentry_value_t value, const char *type, sentry_value_set_by_key(attributes, name, param_obj); } -static sentry_value_t -construct_log(sentry_level_t level, const char *message, va_list args) +/** + * Extracts data from the scope and options, and adds it to the attributes + * as well as directly setting `trace_id` for the log. + * + * We clone most values instead of incref, since they might otherwise change + * between constructing the log & flushing it to an envelope. + */ +static void +add_scope_and_options_data(sentry_value_t log, sentry_value_t attributes) { - sentry_value_t log = sentry_value_new_object(); - sentry_value_t attributes = sentry_value_new_object(); - - va_list args_copy_1, args_copy_2, args_copy_3; - va_copy(args_copy_1, args); - va_copy(args_copy_2, args); - va_copy(args_copy_3, args); - int len = vsnprintf(NULL, 0, message, args_copy_1) + 1; - va_end(args_copy_1); - size_t size = (size_t)len; - char *fmt_message = sentry_malloc(size); - if (!fmt_message) { - va_end(args_copy_2); - va_end(args_copy_3); - return sentry_value_new_null(); - } - - vsnprintf(fmt_message, size, message, args_copy_2); - va_end(args_copy_2); - - sentry_value_set_by_key(log, "body", sentry_value_new_string(fmt_message)); - sentry_free(fmt_message); - sentry_value_set_by_key( - log, "level", sentry_value_new_string(level_as_string(level))); - - // timestamp in seconds - uint64_t usec_time = sentry__usec_time(); - sentry_value_set_by_key(log, "timestamp", - sentry_value_new_double((double)usec_time / 1000000.0)); - SENTRY_WITH_SCOPE_MUT (scope) { - sentry_value_set_by_key(log, "trace_id", - sentry__value_clone(sentry_value_get_by_key( - sentry_value_get_by_key(scope->propagation_context, "trace"), - "trace_id"))); + sentry_value_t trace_id = sentry_value_get_by_key( + sentry_value_get_by_key(scope->propagation_context, "trace"), + "trace_id"); + sentry_value_incref(trace_id); + sentry_value_set_by_key(log, "trace_id", trace_id); sentry_value_t parent_span_id = sentry_value_new_object(); if (scope->transaction_object) { - sentry_value_set_by_key(parent_span_id, "value", - sentry__value_clone(sentry_value_get_by_key( - scope->transaction_object->inner, "span_id"))); - } - - if (scope->span) { - sentry_value_set_by_key(parent_span_id, "value", - sentry__value_clone( - sentry_value_get_by_key(scope->span->inner, "span_id"))); + sentry_value_t span_id = sentry_value_get_by_key( + scope->transaction_object->inner, "span_id"); + sentry_value_incref(span_id); + sentry_value_set_by_key(parent_span_id, "value", span_id); + } else if (scope->span) { + sentry_value_t span_id + = sentry_value_get_by_key(scope->span->inner, "span_id"); + sentry_value_incref(span_id); + sentry_value_set_by_key(parent_span_id, "value", span_id); } sentry_value_set_by_key( parent_span_id, "type", sentry_value_new_string("string")); @@ -279,34 +509,42 @@ construct_log(sentry_level_t level, const char *message, va_list args) if (!sentry_value_is_null(scope->user)) { sentry_value_t user_id = sentry_value_get_by_key(scope->user, "id"); if (!sentry_value_is_null(user_id)) { + sentry_value_incref(user_id); add_attribute(attributes, user_id, "string", "user.id"); } + sentry_value_t user_username = sentry_value_get_by_key(scope->user, "username"); if (!sentry_value_is_null(user_username)) { + sentry_value_incref(user_username); add_attribute(attributes, user_username, "string", "user.name"); } + sentry_value_t user_email = sentry_value_get_by_key(scope->user, "email"); if (!sentry_value_is_null(user_email)) { + sentry_value_incref(user_email); add_attribute(attributes, user_email, "string", "user.email"); } } - sentry_value_t os_context = sentry__get_os_context(); + sentry_value_t os_context + = sentry_value_get_by_key(scope->contexts, "os"); if (!sentry_value_is_null(os_context)) { - sentry_value_t os_name = sentry__value_clone( - sentry_value_get_by_key(os_context, "name")); - sentry_value_t os_version = sentry__value_clone( - sentry_value_get_by_key(os_context, "version")); + sentry_value_t os_name + = sentry_value_get_by_key(os_context, "name"); + sentry_value_t os_version + = sentry_value_get_by_key(os_context, "version"); if (!sentry_value_is_null(os_name)) { + sentry_value_incref(os_name); add_attribute(attributes, os_name, "string", "os.name"); } if (!sentry_value_is_null(os_version)) { + sentry_value_incref(os_version); add_attribute(attributes, os_version, "string", "os.version"); } } - sentry_value_decref(os_context); } + SENTRY_WITH_OPTIONS (options) { if (options->environment) { add_attribute(attributes, @@ -323,11 +561,51 @@ construct_log(sentry_level_t level, const char *message, va_list args) "string", "sentry.sdk.name"); add_attribute(attributes, sentry_value_new_string(sentry_sdk_version()), "string", "sentry.sdk.version"); - add_attribute(attributes, sentry_value_new_string(message), "string", - "sentry.message.template"); +} + +static sentry_value_t +construct_log(sentry_level_t level, const char *message, va_list args) +{ + sentry_value_t log = sentry_value_new_object(); + sentry_value_t attributes = sentry_value_new_object(); + + va_list args_copy_1, args_copy_2, args_copy_3; + va_copy(args_copy_1, args); + va_copy(args_copy_2, args); + va_copy(args_copy_3, args); + int len = vsnprintf(NULL, 0, message, args_copy_1) + 1; + va_end(args_copy_1); + size_t size = (size_t)len; + char *fmt_message = sentry_malloc(size); + if (!fmt_message) { + va_end(args_copy_2); + va_end(args_copy_3); + return sentry_value_new_null(); + } + + vsnprintf(fmt_message, size, message, args_copy_2); + va_end(args_copy_2); + + sentry_value_set_by_key(log, "body", sentry_value_new_string(fmt_message)); + sentry_free(fmt_message); + sentry_value_set_by_key( + log, "level", sentry_value_new_string(level_as_string(level))); + + // timestamp in seconds + uint64_t usec_time = sentry__usec_time(); + sentry_value_set_by_key(log, "timestamp", + sentry_value_new_double((double)usec_time / 1000000.0)); + + // adds data from the scope & options to the attributes, and adds `trace_id` + // to the log + add_scope_and_options_data(log, attributes); // Parse variadic arguments and add them to attributes - populate_message_parameters(attributes, message, args_copy_3); + if (populate_message_parameters(attributes, message, args_copy_3)) { + // only add message template if we have parameters + add_attribute(attributes, sentry_value_new_string(message), "string", + "sentry.message.template"); + } va_end(args_copy_3); sentry_value_set_by_key(log, "attributes", attributes); @@ -335,7 +613,7 @@ construct_log(sentry_level_t level, const char *message, va_list args) return log; } -void +log_return_value_t sentry__logs_log(sentry_level_t level, const char *message, va_list args) { bool enable_logs = false; @@ -344,79 +622,130 @@ sentry__logs_log(sentry_level_t level, const char *message, va_list args) enable_logs = true; } if (enable_logs) { + bool discarded = false; // create log from message sentry_value_t log = construct_log(level, message, args); - - // TODO split up the code below for batched log sending - // e.g. could we store logs on the scope? - sentry_value_t logs = sentry_value_new_object(); - sentry_value_t logs_list = sentry_value_new_list(); - sentry_value_append(logs_list, log); - sentry_value_set_by_key(logs, "items", logs_list); - // sending of the envelope - sentry_envelope_t *envelope = sentry__envelope_new(); - sentry__envelope_add_logs(envelope, logs); - // TODO remove debug write to file below - sentry_envelope_write_to_file(envelope, "logs_envelope.json"); SENTRY_WITH_OPTIONS (options) { - sentry__capture_envelope(options->transport, envelope); + if (options->before_send_log_func) { + log = options->before_send_log_func( + log, options->before_send_log_data); + if (sentry_value_is_null(log)) { + SENTRY_DEBUG( + "log was discarded by the `before_send_log` hook"); + discarded = true; + } + } + } + if (discarded) { + return SENTRY_LOG_RETURN_DISCARD; } - // For now, free the logs object since envelope doesn't take - // ownership - sentry_value_decref(logs); + if (!enqueue_log(log)) { + sentry_value_decref(log); + return SENTRY_LOG_RETURN_FAILED; + } + return SENTRY_LOG_RETURN_SUCCESS; } + return SENTRY_LOG_RETURN_DISABLED; } -void +log_return_value_t sentry_log_trace(const char *message, ...) { va_list args; va_start(args, message); - sentry__logs_log(SENTRY_LEVEL_TRACE, message, args); + log_return_value_t result + = sentry__logs_log(SENTRY_LEVEL_TRACE, message, args); va_end(args); + return result; } -void +log_return_value_t sentry_log_debug(const char *message, ...) { va_list args; va_start(args, message); - sentry__logs_log(SENTRY_LEVEL_DEBUG, message, args); + const log_return_value_t result + = sentry__logs_log(SENTRY_LEVEL_DEBUG, message, args); va_end(args); + return result; } -void +log_return_value_t sentry_log_info(const char *message, ...) { va_list args; va_start(args, message); - sentry__logs_log(SENTRY_LEVEL_INFO, message, args); + const log_return_value_t result + = sentry__logs_log(SENTRY_LEVEL_INFO, message, args); va_end(args); + return result; } -void +log_return_value_t sentry_log_warn(const char *message, ...) { va_list args; va_start(args, message); - sentry__logs_log(SENTRY_LEVEL_WARNING, message, args); + const log_return_value_t result + = sentry__logs_log(SENTRY_LEVEL_WARNING, message, args); va_end(args); + return result; } -void +log_return_value_t sentry_log_error(const char *message, ...) { va_list args; va_start(args, message); - sentry__logs_log(SENTRY_LEVEL_ERROR, message, args); + const log_return_value_t result + = sentry__logs_log(SENTRY_LEVEL_ERROR, message, args); va_end(args); + return result; } -void +log_return_value_t sentry_log_fatal(const char *message, ...) { va_list args; va_start(args, message); - sentry__logs_log(SENTRY_LEVEL_FATAL, message, args); + const log_return_value_t result + = sentry__logs_log(SENTRY_LEVEL_FATAL, message, args); va_end(args); + return result; +} + +void +sentry__logs_startup(void) +{ + sentry__cond_init(&g_logs_state.request_flush); + + sentry__thread_init(&g_logs_state.batching_thread); + int spawn_result = sentry__thread_spawn( + &g_logs_state.batching_thread, batching_thread_func, NULL); + + if (spawn_result == 1) { + SENTRY_ERROR("Failed to start batching thread"); + } +} + +void +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"); + return; + } + sentry__cond_wake(&g_logs_state.request_flush); + sentry__thread_join(g_logs_state.batching_thread); + + // Perform final flush to ensure any remaining logs are sent + flush_logs_queue(); + + sentry__thread_free(&g_logs_state.batching_thread); + + SENTRY_DEBUG("logs system shutdown complete"); } diff --git a/src/sentry_logs.h b/src/sentry_logs.h index 5fa6a4a77..bb5556418 100644 --- a/src/sentry_logs.h +++ b/src/sentry_logs.h @@ -3,6 +3,17 @@ #include "sentry_boot.h" -void sentry__logs_log(sentry_level_t level, const char *message, va_list args); +log_return_value_t sentry__logs_log( + sentry_level_t level, const char *message, va_list args); + +/** + * Sets up the logs timer/flush thread + */ +void sentry__logs_startup(void); + +/** + * Instructs the logs timer/flush thread to shut down. + */ +void sentry__logs_shutdown(uint64_t timeout); #endif diff --git a/src/sentry_options.c b/src/sentry_options.c index 76f3d2352..fa42b33c5 100644 --- a/src/sentry_options.c +++ b/src/sentry_options.c @@ -153,6 +153,14 @@ sentry_options_set_before_transaction( opts->before_transaction_data = user_data; } +void +sentry_options_set_before_send_log(sentry_options_t *opts, + sentry_before_send_log_function_t func, void *user_data) +{ + opts->before_send_log_func = func; + opts->before_send_log_data = user_data; +} + void sentry_options_set_dsn_n( sentry_options_t *opts, const char *raw_dsn, size_t raw_dsn_len) diff --git a/src/sentry_options.h b/src/sentry_options.h index ad7d9b11e..4eb03abc5 100644 --- a/src/sentry_options.h +++ b/src/sentry_options.h @@ -52,6 +52,8 @@ struct sentry_options_s { void *on_crash_data; sentry_transaction_function_t before_transaction_func; void *before_transaction_data; + sentry_before_send_log_function_t before_send_log_func; + void *before_send_log_data; /* Experimentally exposed */ double traces_sample_rate; diff --git a/src/sentry_value.c b/src/sentry_value.c index 2c4d526bc..af4c8709b 100644 --- a/src/sentry_value.c +++ b/src/sentry_value.c @@ -1057,7 +1057,13 @@ sentry__jsonwriter_write_value(sentry_jsonwriter_t *jw, sentry_value_t value) sentry__jsonwriter_write_str(jw, sentry_value_as_string(value)); break; case SENTRY_VALUE_TYPE_LIST: { - const list_t *l = value_as_thing(value)->payload._ptr; + const thing_t *thing = value_as_thing(value); + if (!thing) { + UNREACHABLE("thing of a list is NULL during serialization"); + return; + } + + const list_t *l = thing->payload._ptr; sentry__jsonwriter_write_list_start(jw); for (size_t i = 0; i < l->len; i++) { sentry__jsonwriter_write_value(jw, l->items[i]); @@ -1066,7 +1072,13 @@ sentry__jsonwriter_write_value(sentry_jsonwriter_t *jw, sentry_value_t value) break; } case SENTRY_VALUE_TYPE_OBJECT: { - const obj_t *o = value_as_thing(value)->payload._ptr; + const thing_t *thing = value_as_thing(value); + if (!thing) { + UNREACHABLE("thing of an object is NULL during serialization"); + return; + } + + const obj_t *o = thing->payload._ptr; sentry__jsonwriter_write_object_start(jw); for (size_t i = 0; i < o->len; i++) { sentry__jsonwriter_write_key(jw, o->pairs[i].k); diff --git a/tests/__init__.py b/tests/__init__.py index 255ce8ff3..cfe3e9dd8 100644 --- a/tests/__init__.py +++ b/tests/__init__.py @@ -284,6 +284,7 @@ def deserialize_from( "session", "transaction", "user_report", + "log", ]: rv = cls(headers=headers, payload=PayloadRef(json=json.loads(payload))) else: diff --git a/tests/assertions.py b/tests/assertions.py index eb2c64214..45ae6b060 100644 --- a/tests/assertions.py +++ b/tests/assertions.py @@ -226,6 +226,40 @@ def assert_attachment(envelope): ) +def assert_logs(envelope, expected_item_count=1, expected_trace_id=None): + logs = None + for item in envelope: + assert item.headers.get("type") == "log" + # TODO >= because of random #lost logs in test_logs_threaded + assert item.headers.get("item_count") >= expected_item_count + assert ( + item.headers.get("content_type") == "application/vnd.sentry.items.log+json" + ) + logs = item.payload.json + + assert isinstance(logs, dict) + assert "items" in logs + assert ( + len(logs["items"]) >= expected_item_count + ) # TODO >= because of random #lost logs in test_logs_threaded + # TODO for now, we just check the first item if it looks log-like enough + log_item = logs["items"][0] + assert "body" in log_item + assert "level" in log_item + assert "timestamp" in log_item # TODO do we need to validate the timestamp? + assert "trace_id" in log_item + assert "attributes" in log_item + assert "os.name" in log_item["attributes"] + assert "os.version" in log_item["attributes"] + assert "sentry.environment" in log_item["attributes"] + assert "sentry.release" in log_item["attributes"] + assert "sentry.sdk.name" in log_item["attributes"] + assert "sentry.sdk.version" in log_item["attributes"] + # TODO think about whether we wanna check this; probably yes, to test interaction with tracing + if expected_trace_id: + assert log_item["trace_id"] == expected_trace_id + + def assert_attachment_view_hierarchy(envelope): expected = { "type": "attachment", diff --git a/tests/test_integration_http.py b/tests/test_integration_http.py index 1798c3c45..69640d9d7 100644 --- a/tests/test_integration_http.py +++ b/tests/test_integration_http.py @@ -37,6 +37,7 @@ assert_gzip_file_header, assert_failed_proxy_auth_request, assert_attachment_view_hierarchy, + assert_logs, ) from .conditions import has_http, has_breakpad, has_files @@ -1311,3 +1312,176 @@ def test_capture_with_scope(cmake, httpserver): assert_breadcrumb(envelope, "scoped crumb") assert_attachment(envelope) + + +def test_logs_timer(cmake, httpserver): + tmp_path = cmake(["sentry_example"], {"SENTRY_BACKEND": "none"}) + + # make sure we are isolated from previous runs + shutil.rmtree(tmp_path / ".sentry-native", ignore_errors=True) + + httpserver.expect_request( + "/api/123456/envelope/", + headers={"x-sentry-auth": auth_header}, + ).respond_with_data("OK") + + run( + tmp_path, + "sentry_example", + ["log", "enable-logs", "logs-timer"], + check=True, + env=dict(os.environ, SENTRY_DSN=make_dsn(httpserver)), + ) + + assert len(httpserver.log) == 2 + + req_0 = httpserver.log[0][0] + body_0 = req_0.get_data() + + envelope_0 = Envelope.deserialize(body_0) + assert_logs(envelope_0, 10) + + req_1 = httpserver.log[1][0] + body_1 = req_1.get_data() + + envelope_1 = Envelope.deserialize(body_1) + assert_logs(envelope_1) + + +def test_logs_event(cmake, httpserver): + tmp_path = cmake(["sentry_example"], {"SENTRY_BACKEND": "none"}) + + # make sure we are isolated from previous runs + shutil.rmtree(tmp_path / ".sentry-native", ignore_errors=True) + + httpserver.expect_request( + "/api/123456/envelope/", + headers={"x-sentry-auth": auth_header}, + ).respond_with_data("OK") + + run( + tmp_path, + "sentry_example", + ["log", "enable-logs", "capture-log", "capture-event"], + check=True, + env=dict(os.environ, SENTRY_DSN=make_dsn(httpserver)), + ) + + assert len(httpserver.log) == 2 + + event_req = httpserver.log[0][0] + event_body = event_req.get_data() + + event_envelope = Envelope.deserialize(event_body) + assert_event(event_envelope) + # ensure that the event and the log are part of the same trace + event_trace_id = event_envelope.items[0].payload.json["contexts"]["trace"][ + "trace_id" + ] + + log_req = httpserver.log[1][0] + log_body = log_req.get_data() + + log_envelope = Envelope.deserialize(log_body) + assert_logs(log_envelope, 1, event_trace_id) + + +def test_logs_threaded(cmake, httpserver): + tmp_path = cmake(["sentry_example"], {"SENTRY_BACKEND": "none"}) + + # make sure we are isolated from previous runs + shutil.rmtree(tmp_path / ".sentry-native", ignore_errors=True) + + httpserver.expect_request( + "/api/123456/envelope/", + headers={"x-sentry-auth": auth_header}, + ).respond_with_data("OK") + + # TODO: a significant amount of variability in these tests is due to the "print"-logging to stdout + # i think it is fair to turn them off once these tests should run in CI to get more stable bounds + run( + tmp_path, + "sentry_example", + ["log", "enable-logs", "logs-threads"], + check=True, + env=dict(os.environ, SENTRY_DSN=make_dsn(httpserver)), + ) + + # currently, we drop logs while flushing (local run about 20% if we have 'nonstop' log-calls) + # in CI however, thread scheduling varies greatly, so we sometimes lose all but 1 flush + # TODO update after double buffer, should be closer to 100% captured + assert 1 <= len(httpserver.log) <= 50 + total_count = 0 + + for i in range(len(httpserver.log)): + req = httpserver.log[i][0] + body = req.get_data() + + envelope = Envelope.deserialize(body) + assert_logs(envelope) # TODO what is the expected item count? + total_count += envelope.items[0].headers["item_count"] + print(f"Total amount of captured logs: {total_count}") + assert total_count >= 100 + + +def test_before_send_log(cmake, httpserver): + tmp_path = cmake(["sentry_example"], {"SENTRY_BACKEND": "none"}) + + httpserver.expect_oneshot_request( + "/api/123456/envelope/", + headers={"x-sentry-auth": auth_header}, + ).respond_with_data("OK") + env = dict(os.environ, SENTRY_DSN=make_dsn(httpserver), SENTRY_RELEASE="🤮🚀") + + run( + tmp_path, + "sentry_example", + ["log", "enable-logs", "capture-log", "before-send-log"], + check=True, + env=env, + ) + + assert len(httpserver.log) == 1 + req = httpserver.log[0][0] + body = req.get_data() + + envelope = Envelope.deserialize(body) + + # Show what the envelope looks like if the test fails. + envelope.print_verbose() + + # Extract the log item + (log_item,) = envelope.items + + assert log_item.headers["type"] == "log" + payload = log_item.payload.json + + # Get the first log item from the logs payload + log_entry = payload["items"][0] + attributes = log_entry["attributes"] + + # Check that the before_send_log callback added the expected attribute + assert "coffeepot.size" in attributes + assert attributes["coffeepot.size"]["value"] == "little" + assert attributes["coffeepot.size"]["type"] == "string" + + +def test_before_send_log_discard(cmake, httpserver): + tmp_path = cmake(["sentry_example"], {"SENTRY_BACKEND": "none"}) + + httpserver.expect_oneshot_request( + "/api/123456/envelope/", + headers={"x-sentry-auth": auth_header}, + ).respond_with_data("OK") + env = dict(os.environ, SENTRY_DSN=make_dsn(httpserver), SENTRY_RELEASE="🤮🚀") + + run( + tmp_path, + "sentry_example", + ["log", "enable-logs", "capture-log", "discarding-before-send-log"], + check=True, + env=env, + ) + + # log should have been discarded + assert len(httpserver.log) == 0 diff --git a/tests/unit/test_logs.c b/tests/unit/test_logs.c index 4ad2b4049..0864bda7d 100644 --- a/tests/unit/test_logs.c +++ b/tests/unit/test_logs.c @@ -3,7 +3,13 @@ #include "sentry_envelope.h" -// TODO these tests will need updating after batching is implemented +#ifdef SENTRY_PLATFORM_WINDOWS +# include +# define sleep_ms(MILLISECONDS) Sleep(MILLISECONDS) +#else +# include +# define sleep_ms(MILLISECONDS) usleep(MILLISECONDS * 1000) +#endif static void validate_logs_envelope(sentry_envelope_t *envelope, void *data) @@ -36,6 +42,8 @@ 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); // These should not crash and should respect the enable_logs option sentry_log_trace("Trace message"); @@ -43,11 +51,14 @@ 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_ms(20); sentry_log_fatal("Fatal message"); - sentry_close(); - TEST_CHECK_INT_EQUAL(called_transport, 6); + // TODO for now we set unit test buffer size to 5; does this make sense? + // Or should we just pump out 100+ logs to fill a batch in a for-loop? + TEST_CHECK_INT_EQUAL(called_transport, 2); } SENTRY_TEST(logs_disabled_by_default) @@ -92,9 +103,11 @@ SENTRY_TEST(formatted_log_messages) sentry_log_info("String: %s, Integer: %d, Float: %.2f", "test", 42, 3.14); sentry_log_warn("Character: %c, Hex: 0x%x", 'A', 255); sentry_log_error("Pointer: %p", (void *)0x1234); + sentry_log_error("Big number: %zu", UINT64_MAX); + sentry_log_error("Small number: %d", INT64_MIN); sentry_close(); - // Transport should be called three times - TEST_CHECK_INT_EQUAL(called_transport, 3); + // Transport should be called once + TEST_CHECK_INT_EQUAL(called_transport, 1); }