feat(logs): batching (#1338)

* initial queue attempt

* add timer

* prototype double buffer approach

* update logs unit tests for batching

* replace timer with bgworker

* add first integration tests

* update example.c with correct log thread amounts

* cleanup

* add wait for 'adding' logs in flush logic

* go back to single queue for performance testing

* add time checks

* add ToDos + cleanup sentry_value_t cloning

* initial attempt

* cond_wait for timer + 'adding' spinlock

* add sleep for tests

* add sleep for tests

* force flush before attempting timer_worker shutdown

* add proper cond_wait for 'adding' counter

* revert to manual flush on shutdown instead of timer thread flush

* add separate timer_stop atomic

* cleanup + replace 'adding' cond_wait by pure spinlock

* change bgworker for simpler thread implementation

* cleanup

* fix memleak

* fixes

* cleanup

* cleanup

* windows fixes

* update shutdown order

* fixes

* explicit check to stop timer task

* windows cleanup

* loosen threaded test assertion for CI
- too much variability in thread scheduling, so we can expect pretty much anything

* add continue for unexpected logs flush trigger instead of attempting flush

* Windows re-add condition variable trigger case

* feat(logs): add `before_send_log` (#1355)

* add `before_send_log` callback

* add `before_send_log` callback tests

* (temporary) add debug for calling sentry_options_free

* remove early return

* add late return

* cleanup

* fix ownership issues in single buffer batching (#1362)

* let the producer thread sleep for 1ms between logs

* fix two missing NULL checks in the json serializer

* clean up logging and early exits in `enqueue_log_single()`

* clean up ownerships in logs

* eliminate clones (we expect that everything outlives the logs being sent except local construction)
* use incref everywhere where we ref global state. this was the cause of the UAF, partially solved with the clones but a few were missing. no reason to clone if we do not want to disconnect for a particular object graph
* clarify that add_attribute expects ownership
* minimize scope_mut by moving os_context out
* raise that log output in throughput tests add to variability (stdout logging should be turned off when running a limit)

* log error in case we weren't able to start the log batching worker

* fix clang-cl warning

* ci: fix failing mingw build (#1361)

* ci: fix failing mingw build

* split `ASM_MASM_COMPILER` and `_FLAGS`

* add `ASM_MASM_FLAGS` in `mingw` install step

* specify the `CMAKE_ASM_MASM_COMPILER` as a `FILEPATH`

* clean up CMAKE_DEFINES construction so it is easier to diff in the future

* fix `LLVM_MINGW_INSTALL_PATH` to be referenced locally rather than $env

(cherry picked from commit 519554f)

* use UNREACHABLE macro to fix anal warnings

* batching double buffered (#1365)

* first attempt at double buffered

* remove the sleep from the windows thread func

* clean up thread waiting in the example

* adapt the double buffer to use retries, fix remaining issues, clean up and write inline docs

* return early in example on sentry_init error.

* fix formatting via shorter name for thread gate atomic

* improve inline docs of log_buffer_t members

* fetch os_context from scope

* move scope/options data retrieval into separate function + add expected keys to test

* update logs API to return status code

* cleanup

* add log-event trace connection test

* remove duplicate test

* specify macOS SDKROOT

---------

Co-authored-by: JoshuaMoelans <[email protected]>

* add flush retry for missed flush requests

* move flush retry into flush function

* add docs

---------

Co-authored-by: Mischan Toosarani-Hausberger <[email protected]>

Author: JoshuaMoelans

.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

examples/example.c

@@ -24,6 +24,7 @@
 #    define sleep_s(SECONDS) Sleep((SECONDS) * 1000)
 #else
 
+#    include <pthread.h>
 #    include <signal.h>
 #    include <unistd.h>
 
@@ -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;
 }

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
 

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
+$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
+

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

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;
 }