fix(logs): add logs flush on crash (#1404)

* Add logs-on-crash

* skip crashpad test on macos

* add straight-to-disk writing of log envelopes if crashing

* CHANGELOG.md

* restore thread join for normal shutdown

* directly take log item from httpserver log for crashpad test

* update CHANGELOG.md

* we know which envelope has the log

* we **don't** know which envelope has the log

* add more general request fetch from httpserver function

* add logs return value checks

* fix tsan global data race on logs validation

* move database-path cleanup into the cmake build cache fixture

this eliminates boilerplate noise in the tests but also reduces the chance of forgetting it in a test.

* in the crash-safe logs flush detach the batcher thread and don't wake it since we flush anyway.

* don't clean for unit-test crash_marker

* don't detach in crash-safe but spin-lock in its flusher to acquire flushing.

* add clean parameter to cmake fixture

* ensure logs flushing in crash handlers happens within the handler sync bounds.

* bound the spin lock in the logs flusher during crash-safe mode

* exclude crashed_last_run unit-test from cleaning database paths

* use an unsigned integer for the sleep_time of the crash-safe logs flusher spinlock

* provide cross-platform cpu_relax and replace syscall sleep with spinners.

* isolate `crash_marker` unit test and eliminate exceptions to database cleaning in the pytest configuration

* platform path special case in crash_marker unit test

* crashed_last_run can no longer assume that a database path exists

this means when it does its clearing a TEST_CHECK cannot assume that a directory even exists (in which case clear_crash_marker would actually fail versus the case were only the marker file didn't exist).

* clean up log statements

* bump CI python to 3.12

* fix CHANGELOG.md

---------

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

Author: JoshuaMoelans

.github/workflows/benchmark.yml

@@ -37,7 +37,7 @@ jobs:
 
       - uses: actions/setup-python@v5
         with:
-          python-version: "3.11"
+          python-version: "3.12"
           cache: "pip"
 
       - name: Install Linux dependencies

.github/workflows/ci.yml

@@ -189,7 +189,7 @@ jobs:
           submodules: recursive
       - uses: actions/setup-python@v5
         with:
-          python-version: ${{ !env['SYSTEM_PYTHON'] && '3.11' || '' }}
+          python-version: ${{ !env['SYSTEM_PYTHON'] && '3.12' || '' }}
           cache: "pip"
 
       - name: Installing Linux Dependencies

CHANGELOG.md

@@ -1,5 +1,11 @@
 # Changelog
 
+## Unreleased
+
+**Fixes**:
+
+- Add logs flush on crash. This is not available for macOS with the `crashpad` backend. ([#1404](https://github.com/getsentry/sentry-native/pull/1404))
+
 ## 0.11.3
 
 **Features**:

src/CMakeLists.txt

@@ -8,6 +8,7 @@ sentry_target_sources_cwd(sentry
 	sentry_boot.h
 	sentry_core.c
 	sentry_core.h
+	sentry_cpu_relax.h
 	sentry_database.c
 	sentry_database.h
 	sentry_envelope.c

src/backends/sentry_backend_breakpad.cpp

@@ -8,6 +8,7 @@ extern "C" {
 #include "sentry_database.h"
 #include "sentry_envelope.h"
 #include "sentry_logger.h"
+#include "sentry_logs.h"
 #include "sentry_options.h"
 #ifdef SENTRY_PLATFORM_WINDOWS
 #    include "sentry_os.h"
@@ -125,6 +126,11 @@ breakpad_backend_callback(const google_breakpad::MinidumpDescriptor &descriptor,
         event, "level", sentry__value_new_level(SENTRY_LEVEL_FATAL));
 
     SENTRY_WITH_OPTIONS (options) {
+        // Flush logs in a crash-safe manner before crash handling
+        if (options->enable_logs) {
+            sentry__logs_flush_crash_safe();
+        }
+
         sentry__write_crash_marker(options);
 
         bool should_handle = true;

src/backends/sentry_backend_crashpad.cpp

@@ -5,9 +5,11 @@ extern "C" {
 #include "sentry_attachment.h"
 #include "sentry_backend.h"
 #include "sentry_core.h"
+#include "sentry_cpu_relax.h"
 #include "sentry_database.h"
 #include "sentry_envelope.h"
 #include "sentry_logger.h"
+#include "sentry_logs.h"
 #include "sentry_options.h"
 #ifdef SENTRY_PLATFORM_WINDOWS
 #    include "sentry_os.h"
@@ -287,6 +289,7 @@ flush_scope_from_handler(
     while (!state->scope_flush.compare_exchange_strong(
         expected, true, std::memory_order_acquire)) {
         expected = false;
+        sentry__cpu_relax();
     }
 
     // now we are the sole flusher and can flush into the crash event
@@ -305,6 +308,7 @@ static bool
 sentry__crashpad_handler(int signum, siginfo_t *info, ucontext_t *user_context)
 {
     sentry__page_allocator_enable();
+    sentry__enter_signal_handler();
 #    endif
     // Disable logging during crash handling if the option is set
     SENTRY_WITH_OPTIONS (options) {
@@ -318,6 +322,10 @@ sentry__crashpad_handler(int signum, siginfo_t *info, ucontext_t *user_context)
     bool should_dump = true;
 
     SENTRY_WITH_OPTIONS (options) {
+        // Flush logs in a crash-safe manner before crash handling
+        if (options->enable_logs) {
+            sentry__logs_flush_crash_safe();
+        }
         auto state = static_cast<crashpad_state_t *>(options->backend->data);
         sentry_value_t crash_event
             = sentry__value_new_event_with_id(&state->crash_event_id);
@@ -404,6 +412,10 @@ sentry__crashpad_handler(int signum, siginfo_t *info, ucontext_t *user_context)
 #    endif
     }
 
+#    ifndef SENTRY_PLATFORM_WINDOWS
+    sentry__leave_signal_handler();
+#    endif
+
     // we did not "handle" the signal, so crashpad should do that.
     return false;
 }

src/backends/sentry_backend_inproc.c

@@ -7,6 +7,7 @@
 #include "sentry_database.h"
 #include "sentry_envelope.h"
 #include "sentry_logger.h"
+#include "sentry_logs.h"
 #include "sentry_options.h"
 #if defined(SENTRY_PLATFORM_WINDOWS)
 #    include "sentry_os.h"
@@ -555,6 +556,10 @@ handle_ucontext(const sentry_ucontext_t *uctx)
 #endif
 
     SENTRY_WITH_OPTIONS (options) {
+        // Flush logs in a crash-safe manner before crash handling
+        if (options->enable_logs) {
+            sentry__logs_flush_crash_safe();
+        }
 #ifdef SENTRY_PLATFORM_LINUX
         // On Linux (and thus Android) CLR/Mono converts signals provoked by
         // AOT/JIT-generated native code into managed code exceptions. In these

src/sentry_cpu_relax.h

@@ -0,0 +1,31 @@
+#ifndef SENTRY_CPU_RELAX_H_INCLUDED
+#define SENTRY_CPU_RELAX_H_INCLUDED
+
+#if defined(_MSC_VER)
+#    include <intrin.h>
+#    if defined(_M_IX86) || defined(_M_X64)
+#        define sentry__cpu_relax() _mm_pause()
+#    elif defined(_M_ARM) || defined(_M_ARM64)
+#        define sentry__cpu_relax() __yield()
+#    else
+#        define sentry__cpu_relax() __nop()
+#    endif
+#else
+#    if defined(__i386__) || defined(__x86_64__) || defined(__amd64__)
+#        define sentry__cpu_relax() __asm__ __volatile__("pause")
+#    elif defined(__aarch64__) || defined(__arm__)
+#        define sentry__cpu_relax() __asm__ __volatile__("yield")
+#    elif defined(__powerpc__) || defined(__ppc__) || defined(__PPC__)
+#        define sentry__cpu_relax() __asm__ __volatile__("or 27,27,27")
+#    elif defined(__riscv)
+#        if defined(__riscv_zihintpause)
+#            define sentry__cpu_relax() __asm__ __volatile__("pause")
+#        else
+#            define sentry__cpu_relax() __asm__ __volatile__("nop")
+#        endif
+#    else
+#        define sentry__cpu_relax() (void)0
+#    endif
+#endif
+
+#endif // SENTRY_CPU_RELAX_H_INCLUDED

src/sentry_logs.c

@@ -1,30 +1,28 @@
 #include "sentry_logs.h"
 #include "sentry_core.h"
+#include "sentry_cpu_relax.h"
 #include "sentry_envelope.h"
 #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 <stdarg.h>
 #include <string.h>
 
 #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
 
+#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
 /**
  * Thread lifecycle states for the logs batching thread.
  */
@@ -87,13 +85,49 @@ check_for_flush_condition(void)
     return sentry__atomic_fetch(&current_buf->index) >= QUEUE_LENGTH;
 }
 
+// Use a sleep spinner around a monotonic timer so we don't syscall sleep from
+// a signal handler. While this is strictly needed only there, there is no
+// reason not to use the same implementation across platforms.
 static void
-flush_logs_queue(void)
+crash_safe_sleep_ms(uint64_t delay_ms)
 {
-    const long already_flushing
-        = sentry__atomic_store(&g_logs_state.flushing, 1);
-    if (already_flushing) {
-        return;
+    const uint64_t start = sentry__monotonic_time();
+    const uint64_t end = start + delay_ms;
+    while (sentry__monotonic_time() < end) {
+        for (int i = 0; i < 64; i++) {
+            sentry__cpu_relax();
+        }
+    }
+}
+
+static void
+flush_logs_queue(bool crash_safe)
+{
+    if (crash_safe) {
+        // In crash-safe mode, spin lock with timeout and backoff
+        int attempts = 0;
+        while (!sentry__atomic_compare_swap(&g_logs_state.flushing, 0, 1)) {
+            const int max_attempts = 200;
+            if (++attempts > max_attempts) {
+                SENTRY_WARN("flush_logs_queue: timeout waiting for flushing "
+                            "lock in crash-safe mode");
+                return;
+            }
+
+            // backoff max-wait with max_attempts = 200 based sleep slots:
+            // 9ms + 450ms + 1010ms = 1500ish ms
+            const uint32_t sleep_time = (attempts < 10) ? 1
+                : (attempts < 100)                      ? 5
+                                                        : 10;
+            crash_safe_sleep_ms(sleep_time);
+        }
+    } else {
+        // Normal mode: try once and return if already flushing
+        const long already_flushing
+            = sentry__atomic_store(&g_logs_state.flushing, 1);
+        if (already_flushing) {
+            return;
+        }
     }
     do {
         // prep both buffers
@@ -115,10 +149,7 @@ flush_logs_queue(void)
 
         // 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);
@@ -139,8 +170,17 @@ flush_logs_queue(void)
 
             sentry_envelope_t *envelope = sentry__envelope_new();
             sentry__envelope_add_logs(envelope, logs);
+
             SENTRY_WITH_OPTIONS (options) {
-                sentry__capture_envelope(options->transport, envelope);
+                if (crash_safe) {
+                    // Write directly to disk to avoid transport queuing during
+                    // crash
+                    sentry__run_write_envelope(options->run, envelope);
+                    sentry_envelope_free(envelope);
+                } else {
+                    // Normal operation: use transport for HTTP transmission
+                    sentry__capture_envelope(options->transport, envelope);
+                }
             }
             sentry_value_decref(logs);
         }
@@ -260,20 +300,20 @@ batching_thread_func(void *data)
         case 0:
 #ifdef SENTRY_PLATFORM_WINDOWS
             if (GetLastError() == ERROR_TIMEOUT) {
-                SENTRY_DEBUG("Logs flushed by timeout");
+                SENTRY_TRACE("Logs flushed by timeout");
                 break;
             }
 #endif
-            SENTRY_DEBUG("Logs flushed by filled buffer");
+            SENTRY_TRACE("Logs flushed by filled buffer");
             break;
 #ifdef SENTRY_PLATFORM_UNIX
         case ETIMEDOUT:
-            SENTRY_DEBUG("Logs flushed by timeout");
+            SENTRY_TRACE("Logs flushed by timeout");
             break;
 #endif
 #ifdef SENTRY_PLATFORM_WINDOWS
         case 1:
-            SENTRY_DEBUG("Logs flushed by filled buffer");
+            SENTRY_TRACE("Logs flushed by filled buffer");
             break;
 #endif
         default:
@@ -282,7 +322,7 @@ batching_thread_func(void *data)
         }
 
         // Try to flush logs
-        flush_logs_queue();
+        flush_logs_queue(false);
     }
 
     sentry__mutex_unlock(&task_lock);
@@ -833,13 +873,37 @@ sentry__logs_shutdown(uint64_t timeout)
     sentry__thread_join(g_logs_state.batching_thread);
 
     // Perform final flush to ensure any remaining logs are sent
-    flush_logs_queue();
+    flush_logs_queue(false);
 
     sentry__thread_free(&g_logs_state.batching_thread);
 
     SENTRY_DEBUG("logs system shutdown complete");
 }
 
+void
+sentry__logs_flush_crash_safe(void)
+{
+    SENTRY_DEBUG("crash-safe logs flush");
+
+    // Check if logs system is initialized
+    const long state = sentry__atomic_fetch(&g_logs_state.thread_state);
+    if (state == SENTRY_LOGS_THREAD_STOPPED) {
+        return;
+    }
+
+    // Signal the thread to stop but don't wait, since the crash-safe flush
+    // will spin-lock on flushing anyway.
+    sentry__atomic_store(
+        &g_logs_state.thread_state, (long)SENTRY_LOGS_THREAD_STOPPED);
+
+    // Perform crash-safe flush directly to disk to avoid transport queuing
+    // This is safe because we're in a crash scenario and the main thread
+    // is likely dead or dying anyway
+    flush_logs_queue(true);
+
+    SENTRY_DEBUG("crash-safe logs flush complete");
+}
+
 #ifdef SENTRY_UNITTEST
 /**
  * Wait for the logs batching thread to be ready.

src/sentry_logs.h

@@ -16,6 +16,13 @@ void sentry__logs_startup(void);
  */
 void sentry__logs_shutdown(uint64_t timeout);
 
+/**
+ * Crash-safe logs flush that avoids thread synchronization.
+ * This should be used during crash handling to flush logs without
+ * waiting for the batching thread to shut down cleanly.
+ */
+void sentry__logs_flush_crash_safe(void);
+
 #ifdef SENTRY_UNITTEST
 int populate_message_parameters(
     sentry_value_t attributes, const char *message, va_list args);