From 8701a315cd3c00c79f5a14ecb9a3694a150ffa43 Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Wed, 11 Jun 2025 17:37:40 +0200 Subject: [PATCH 01/14] add sentry logs option --- include/sentry.h | 9 +++++++++ src/sentry_options.c | 12 ++++++++++++ src/sentry_options.h | 1 + 3 files changed, 22 insertions(+) diff --git a/include/sentry.h b/include/sentry.h index 6314c374c..b5ceb617a 100644 --- a/include/sentry.h +++ b/include/sentry.h @@ -1741,6 +1741,15 @@ typedef double (*sentry_traces_sampler_function)( SENTRY_EXPERIMENTAL_API void sentry_options_set_traces_sampler( sentry_options_t *opts, sentry_traces_sampler_function callback); +/** + * Enables or disables the structured logging feature. + * When disabled, all calls to sentry_logger_X() are no-ops. + */ +SENTRY_EXPERIMENTAL_API void sentry_options_set_enable_logs( + sentry_options_t *opts, int enable_logs); +SENTRY_EXPERIMENTAL_API int sentry_options_get_enable_logs( + const sentry_options_t *opts); + #ifdef SENTRY_PLATFORM_LINUX /** diff --git a/src/sentry_options.c b/src/sentry_options.c index 0bfb70b10..a940d8ff3 100644 --- a/src/sentry_options.c +++ b/src/sentry_options.c @@ -702,6 +702,18 @@ sentry_options_set_backend(sentry_options_t *opts, sentry_backend_t *backend) opts->backend = backend; } +void +sentry_options_set_enable_logs(sentry_options_t *opts, int enable_logs) +{ + opts->enable_logs = !!enable_logs; +} + +int +sentry_options_get_enable_logs(const sentry_options_t *opts) +{ + return opts->enable_logs; +} + #ifdef SENTRY_PLATFORM_LINUX sentry_handler_strategy_t diff --git a/src/sentry_options.h b/src/sentry_options.h index 0185bc67c..3a066ee95 100644 --- a/src/sentry_options.h +++ b/src/sentry_options.h @@ -75,6 +75,7 @@ struct sentry_options_s { double traces_sample_rate; sentry_traces_sampler_function traces_sampler; size_t max_spans; + bool enable_logs; /* everything from here on down are options which are stored here but not exposed through the options API */ From c83b3ee5bf2d895b1a277a819b5e4ba249c595ad Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Thu, 12 Jun 2025 11:44:59 +0200 Subject: [PATCH 02/14] add sentry logs option to example --- examples/example.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/examples/example.c b/examples/example.c index b6897cfaf..4e1790d5d 100644 --- a/examples/example.c +++ b/examples/example.c @@ -353,6 +353,10 @@ main(int argc, char **argv) sentry_options_add_view_hierarchy(options, "./view-hierarchy.json"); } + if (has_arg(argc, argv, "enable-logs")) { + sentry_options_set_enable_logs(options, true); + } + sentry_init(options); if (!has_arg(argc, argv, "no-setup")) { From 4ede81213831ddff336e369871f1bddb2d2c7122 Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Mon, 28 Jul 2025 12:58:21 +0200 Subject: [PATCH 03/14] feat(logs): add sentry log API + send first logs (#1272) * add sentry log API + send first logs * fix log_level_as_string * attach attributes to logs * attach formatted message + args * add to example * add more attributes * cleanup * windows warning-as-error * windows warning-as-error v2 * windows warning-as-error v2 (final) * add unit tests for initial logs * memleak attempted fix * memleak attempted fix 2 * cleanup * use `sentry_level_t` instead of new log level enum * add SENTRY_LEVEL_TRACE to sentry_logger * quick anti-brownout fix - see https://github.com/getsentry/sentry-native/pull/1274 * fix missing SENTRY_LEVEL_INFO string return * fix logger level check + add test * cleanup logs parameter extraction * warn-as-error fix * const char* fix * static function * feat(logs): add (u)int64 sentry_value_t type (#1301) * add (u)int64 sentry_value_t type * add value_to_msgpack missing switch cases * remove undefined behavior test (C99 6.3.1.4) * avoid Windows sized integer name collision * cleanup & apply code review feedback * more cleanup & remove type coercion * update logs param conversion * own uint64 string * apply suggestions from code review --- .github/workflows/ci.yml | 2 +- examples/example.c | 23 +++ include/sentry.h | 30 +++ src/CMakeLists.txt | 2 + src/sentry_core.c | 1 + src/sentry_envelope.c | 26 +++ src/sentry_envelope.h | 6 + src/sentry_json.c | 20 ++ src/sentry_json.h | 10 + src/sentry_logger.c | 5 +- src/sentry_logger.h | 5 + src/sentry_logs.c | 421 ++++++++++++++++++++++++++++++++++++++ src/sentry_logs.h | 8 + src/sentry_string.h | 11 + src/sentry_value.c | 162 +++++++++++++-- tests/unit/CMakeLists.txt | 1 + tests/unit/test_logger.c | 66 ++++++ tests/unit/test_logs.c | 100 +++++++++ tests/unit/test_value.c | 110 +++++++++- tests/unit/tests.inc | 6 + 20 files changed, 993 insertions(+), 22 deletions(-) create mode 100644 src/sentry_logs.c create mode 100644 src/sentry_logs.h create mode 100644 tests/unit/test_logs.c diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 74ae91cbf..a8b13fc9f 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -121,7 +121,7 @@ jobs: SYSTEM_VERSION_COMPAT: 0 RUN_ANALYZER: asan,llvm-cov - name: Windows (old VS, 32-bit) - os: windows-2019 + os: windows-2022 TEST_X86: 1 - name: Windows (latest) os: windows-latest diff --git a/examples/example.c b/examples/example.c index 4e1790d5d..9f6602822 100644 --- a/examples/example.c +++ b/examples/example.c @@ -359,6 +359,26 @@ main(int argc, char **argv) sentry_init(options); + // TODO incorporate into test + if (sentry_options_get_enable_logs(options)) { + 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, "no-setup")) { sentry_set_transaction("test-transaction"); sentry_set_level(SENTRY_LEVEL_WARNING); @@ -566,6 +586,9 @@ main(int argc, char **argv) SENTRY_LEVEL_INFO, "my-logger", "Hello World!"); sentry_capture_event(event); } + if (sentry_options_get_enable_logs(options)) { + sentry_log_debug("logging after scoped transaction event"); + } sentry_transaction_finish(tx); } diff --git a/include/sentry.h b/include/sentry.h index b5ceb617a..0a9ccb62d 100644 --- a/include/sentry.h +++ b/include/sentry.h @@ -137,6 +137,8 @@ typedef enum { SENTRY_VALUE_TYPE_NULL, SENTRY_VALUE_TYPE_BOOL, SENTRY_VALUE_TYPE_INT32, + SENTRY_VALUE_TYPE_INT64, + SENTRY_VALUE_TYPE_UINT64, SENTRY_VALUE_TYPE_DOUBLE, SENTRY_VALUE_TYPE_STRING, SENTRY_VALUE_TYPE_LIST, @@ -200,6 +202,16 @@ SENTRY_API sentry_value_t sentry_value_new_null(void); */ SENTRY_API sentry_value_t sentry_value_new_int32(int32_t value); +/** + * Creates a new 64-bit signed integer value. + */ +SENTRY_API sentry_value_t sentry_value_new_int64(int64_t value); + +/** + * Creates a new 64-bit unsigned integer value. + */ +SENTRY_API sentry_value_t sentry_value_new_uint64(uint64_t value); + /** * Creates a new double value. */ @@ -338,6 +350,16 @@ SENTRY_API size_t sentry_value_get_length(sentry_value_t value); */ SENTRY_API int32_t sentry_value_as_int32(sentry_value_t value); +/** + * Converts a value into a 64 bit signed integer. + */ +SENTRY_API int64_t sentry_value_as_int64(sentry_value_t value); + +/** + * Converts a value into a 64 bit unsigned integer. + */ +SENTRY_API uint64_t sentry_value_as_uint64(sentry_value_t value); + /** * Converts a value into a double value. */ @@ -370,6 +392,7 @@ SENTRY_API char *sentry_value_to_json(sentry_value_t value); * Sentry levels for events and breadcrumbs. */ typedef enum sentry_level_e { + SENTRY_LEVEL_TRACE = -2, SENTRY_LEVEL_DEBUG = -1, SENTRY_LEVEL_INFO = 0, SENTRY_LEVEL_WARNING = 1, @@ -1750,6 +1773,13 @@ 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, ...); + #ifdef SENTRY_PLATFORM_LINUX /** diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index 700f79753..171da4ab1 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -15,6 +15,8 @@ sentry_target_sources_cwd(sentry sentry_json.h sentry_logger.c sentry_logger.h + sentry_logs.c + sentry_logs.h sentry_options.c sentry_options.h sentry_os.c diff --git a/src/sentry_core.c b/src/sentry_core.c index 24d7a94bf..0bcfd2472 100644 --- a/src/sentry_core.c +++ b/src/sentry_core.c @@ -125,6 +125,7 @@ sentry_init(sentry_options_t *options) sentry_close(); sentry_logger_t logger = { NULL, NULL, SENTRY_LEVEL_DEBUG }; + if (options->debug) { logger = options->logger; } diff --git a/src/sentry_envelope.c b/src/sentry_envelope.c index 137115c86..da67ae2de 100644 --- a/src/sentry_envelope.c +++ b/src/sentry_envelope.c @@ -295,6 +295,32 @@ sentry__envelope_add_transaction( return item; } +sentry_envelope_item_t * +sentry__envelope_add_logs(sentry_envelope_t *envelope, sentry_value_t logs) +{ + sentry_envelope_item_t *item = envelope_add_item(envelope); + if (!item) { + return NULL; + } + + sentry_jsonwriter_t *jw = sentry__jsonwriter_new_sb(NULL); + if (!jw) { + return NULL; + } + + sentry__jsonwriter_write_value(jw, logs); + item->payload = sentry__jsonwriter_into_string(jw, &item->payload_len); + + 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__envelope_item_set_header(item, "content_type", + sentry_value_new_string("application/vnd.sentry.items.log+json")); + + return item; +} + sentry_envelope_item_t * sentry__envelope_add_user_feedback( sentry_envelope_t *envelope, sentry_value_t user_feedback) diff --git a/src/sentry_envelope.h b/src/sentry_envelope.h index 842cbb475..4cfc7d90f 100644 --- a/src/sentry_envelope.h +++ b/src/sentry_envelope.h @@ -42,6 +42,12 @@ sentry_envelope_item_t *sentry__envelope_add_event( sentry_envelope_item_t *sentry__envelope_add_transaction( sentry_envelope_t *envelope, sentry_value_t transaction); +/** + * Add a list of logs to this envelope. + */ +sentry_envelope_item_t *sentry__envelope_add_logs( + sentry_envelope_t *envelope, sentry_value_t logs); + /** * Add a user feedback to this envelope. */ diff --git a/src/sentry_json.c b/src/sentry_json.c index 8902406f7..ea7454f81 100644 --- a/src/sentry_json.c +++ b/src/sentry_json.c @@ -364,6 +364,26 @@ sentry__jsonwriter_write_int32(sentry_jsonwriter_t *jw, int32_t val) } } +void +sentry__jsonwriter_write_int64(sentry_jsonwriter_t *jw, int64_t val) +{ + if (can_write_item(jw)) { + char buf[24]; + snprintf(buf, sizeof(buf), "%" PRId64, val); + write_str(jw, buf); + } +} + +void +sentry__jsonwriter_write_uint64(sentry_jsonwriter_t *jw, uint64_t val) +{ + if (can_write_item(jw)) { + char buf[24]; + snprintf(buf, sizeof(buf), "%" PRIu64, val); + write_str(jw, buf); + } +} + void sentry__jsonwriter_write_double(sentry_jsonwriter_t *jw, double val) { diff --git a/src/sentry_json.h b/src/sentry_json.h index 1467547c0..20f302518 100644 --- a/src/sentry_json.h +++ b/src/sentry_json.h @@ -53,6 +53,16 @@ void sentry__jsonwriter_write_bool(sentry_jsonwriter_t *jw, bool val); */ void sentry__jsonwriter_write_int32(sentry_jsonwriter_t *jw, int32_t val); +/** + * Write a 64-bit signed integer, encoded as JSON number. + */ +void sentry__jsonwriter_write_int64(sentry_jsonwriter_t *jw, int64_t val); + +/** + * Write a 64-bit unsigned integer, encoded as JSON number. + */ +void sentry__jsonwriter_write_uint64(sentry_jsonwriter_t *jw, uint64_t val); + /** * Write a 64-bit float, encoded as JSON number. */ diff --git a/src/sentry_logger.c b/src/sentry_logger.c index 98b965d7a..642c9433c 100644 --- a/src/sentry_logger.c +++ b/src/sentry_logger.c @@ -69,6 +69,8 @@ const char * sentry__logger_describe(sentry_level_t level) { switch (level) { + case SENTRY_LEVEL_TRACE: + return "TRACE "; case SENTRY_LEVEL_DEBUG: return "DEBUG "; case SENTRY_LEVEL_INFO: @@ -87,8 +89,7 @@ sentry__logger_describe(sentry_level_t level) void sentry__logger_log(sentry_level_t level, const char *message, ...) { - if (g_logger.logger_level != SENTRY_LEVEL_DEBUG - && level < g_logger.logger_level) { + if (level < g_logger.logger_level) { return; } sentry_logger_t logger = g_logger; diff --git a/src/sentry_logger.h b/src/sentry_logger.h index af21b016d..14e4d0451 100644 --- a/src/sentry_logger.h +++ b/src/sentry_logger.h @@ -18,6 +18,11 @@ const char *sentry__logger_describe(sentry_level_t level); void sentry__logger_log(sentry_level_t level, const char *message, ...); +#define SENTRY_TRACEF(message, ...) \ + sentry__logger_log(SENTRY_LEVEL_TRACE, message, __VA_ARGS__) + +#define SENTRY_TRACE(message) sentry__logger_log(SENTRY_LEVEL_TRACE, message) + #define SENTRY_DEBUGF(message, ...) \ sentry__logger_log(SENTRY_LEVEL_DEBUG, message, __VA_ARGS__) diff --git a/src/sentry_logs.c b/src/sentry_logs.c new file mode 100644 index 000000000..9f87e3bd9 --- /dev/null +++ b/src/sentry_logs.c @@ -0,0 +1,421 @@ +#include "sentry_logs.h" +#include "sentry_core.h" +#include "sentry_envelope.h" +#include "sentry_options.h" +#include "sentry_os.h" +#include "sentry_scope.h" + +#include +#include + +static const char * +level_as_string(sentry_level_t level) +{ + switch (level) { + case SENTRY_LEVEL_TRACE: + return "trace"; + case SENTRY_LEVEL_DEBUG: + return "debug"; + case SENTRY_LEVEL_INFO: + return "info"; + case SENTRY_LEVEL_WARNING: + return "warn"; + case SENTRY_LEVEL_ERROR: + return "error"; + case SENTRY_LEVEL_FATAL: + return "fatal"; + default: + return "unknown"; + } +} + +static sentry_value_t +construct_param_from_conversion(const char conversion, va_list *args_copy) +{ + sentry_value_t param_obj = sentry_value_new_object(); + switch (conversion) { + case 'd': + case 'i': { + int val = va_arg(*args_copy, int); + sentry_value_set_by_key( + param_obj, "value", sentry_value_new_int64(val)); + sentry_value_set_by_key( + param_obj, "type", sentry_value_new_string("integer")); + break; + } + case 'u': + case 'x': + case 'X': + case 'o': { + unsigned int val = va_arg(*args_copy, unsigned int); + sentry_value_set_by_key(param_obj, "value", + sentry__value_new_string_owned(sentry__uint64_to_string(val))); + sentry_value_set_by_key( + param_obj, "type", sentry_value_new_string("string")); + break; + } + case 'f': + case 'F': + case 'e': + case 'E': + case 'g': + case 'G': { + double val = va_arg(*args_copy, double); + sentry_value_set_by_key( + param_obj, "value", sentry_value_new_double(val)); + sentry_value_set_by_key( + param_obj, "type", sentry_value_new_string("double")); + break; + } + case 'c': { + int val = va_arg(*args_copy, int); + char str[2] = { (char)val, '\0' }; + sentry_value_set_by_key( + param_obj, "value", sentry_value_new_string(str)); + sentry_value_set_by_key( + param_obj, "type", sentry_value_new_string("string")); + break; + } + case 's': { + const char *val = va_arg(*args_copy, const char *); + if (val) { + sentry_value_set_by_key( + param_obj, "value", sentry_value_new_string(val)); + } else { + sentry_value_set_by_key( + param_obj, "value", sentry_value_new_string("(null)")); + } + sentry_value_set_by_key( + param_obj, "type", sentry_value_new_string("string")); + break; + } + case 'p': { + void *val = va_arg(*args_copy, void *); + char ptr_str[32]; + snprintf(ptr_str, sizeof(ptr_str), "%p", val); + sentry_value_set_by_key( + param_obj, "value", sentry_value_new_string(ptr_str)); + sentry_value_set_by_key( + param_obj, "type", sentry_value_new_string("string")); + break; + } + default: + // Unknown format specifier, skip the argument + (void)va_arg(*args_copy, void *); + sentry_value_set_by_key( + param_obj, "value", sentry_value_new_string("(unknown)")); + sentry_value_set_by_key( + param_obj, "type", sentry_value_new_string("string")); + break; + } + + return param_obj; +} + +static const char * +skip_flags(const char *fmt_ptr) +{ + while (*fmt_ptr + && (*fmt_ptr == '-' || *fmt_ptr == '+' || *fmt_ptr == ' ' + || *fmt_ptr == '#' || *fmt_ptr == '0')) { + fmt_ptr++; + } + return fmt_ptr; +} + +static const char * +skip_width(const char *fmt_ptr) +{ + while (*fmt_ptr && (*fmt_ptr >= '0' && *fmt_ptr <= '9')) { + fmt_ptr++; + } + return fmt_ptr; +} + +static const char * +skip_precision(const char *fmt_ptr) +{ + + if (*fmt_ptr == '.') { + fmt_ptr++; + while (*fmt_ptr && (*fmt_ptr >= '0' && *fmt_ptr <= '9')) { + fmt_ptr++; + } + } + return fmt_ptr; +} + +static const char * +skip_length(const char *fmt_ptr) +{ + while (*fmt_ptr + && (*fmt_ptr == 'h' || *fmt_ptr == 'l' || *fmt_ptr == 'L' + || *fmt_ptr == 'z' || *fmt_ptr == 'j' || *fmt_ptr == 't')) { + fmt_ptr++; + } + return fmt_ptr; +} + +static void +populate_message_parameters( + sentry_value_t attributes, const char *message, va_list args) +{ + if (!message || sentry_value_is_null(attributes)) { + return; + } + + const char *fmt_ptr = message; + int param_index = 0; + va_list args_copy; + va_copy(args_copy, args); + + while (*fmt_ptr) { + // Find the next format specifier + if (*fmt_ptr == '%') { + fmt_ptr++; // Skip the '%' + + if (*fmt_ptr == '%') { + // Escaped '%', not a format specifier + fmt_ptr++; + continue; + } + + fmt_ptr = skip_flags(fmt_ptr); + fmt_ptr = skip_width(fmt_ptr); + fmt_ptr = skip_precision(fmt_ptr); + fmt_ptr = skip_length(fmt_ptr); + + // Get the conversion specifier + char conversion = *fmt_ptr; + if (conversion) { + char key[64]; + snprintf(key, sizeof(key), "sentry.message.parameter.%d", + param_index); + sentry_value_t param_obj + = construct_param_from_conversion(conversion, &args_copy); + sentry_value_set_by_key(attributes, key, param_obj); + param_index++; + fmt_ptr++; + } + } else { + fmt_ptr++; + } + } + + va_end(args_copy); +} + +static void +add_attribute(sentry_value_t attributes, sentry_value_t value, const char *type, + const char *name) +{ + sentry_value_t param_obj = sentry_value_new_object(); + sentry_value_set_by_key(param_obj, "value", value); + sentry_value_set_by_key(param_obj, "type", sentry_value_new_string(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) +{ + 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 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_set_by_key( + parent_span_id, "type", sentry_value_new_string("string")); + if (scope->transaction_object || scope->span) { + sentry_value_set_by_key( + attributes, "sentry.trace.parent_span_id", parent_span_id); + } else { + sentry_value_decref(parent_span_id); + } + + 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)) { + 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)) { + 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)) { + add_attribute(attributes, user_email, "string", "user.email"); + } + } + sentry_value_t os_context = sentry__get_os_context(); + 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")); + if (!sentry_value_is_null(os_name)) { + add_attribute(attributes, os_name, "string", "os.name"); + } + if (!sentry_value_is_null(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, + sentry_value_new_string(options->environment), "string", + "sentry.environment"); + } + if (options->release) { + add_attribute(attributes, sentry_value_new_string(options->release), + "string", "sentry.release"); + } + } + + add_attribute(attributes, sentry_value_new_string("sentry.native"), + "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"); + + // Parse variadic arguments and add them to attributes + populate_message_parameters(attributes, message, args_copy_3); + va_end(args_copy_3); + + sentry_value_set_by_key(log, "attributes", attributes); + + return log; +} + +void +sentry__logs_log(sentry_level_t level, const char *message, va_list args) +{ + bool enable_logs = false; + SENTRY_WITH_OPTIONS (options) { + if (options->enable_logs) + enable_logs = true; + } + if (enable_logs) { + // 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); + } + // For now, free the logs object since envelope doesn't take + // ownership + sentry_value_decref(logs); + } +} + +void +sentry_log_trace(const char *message, ...) +{ + va_list args; + va_start(args, message); + sentry__logs_log(SENTRY_LEVEL_TRACE, message, args); + va_end(args); +} + +void +sentry_log_debug(const char *message, ...) +{ + va_list args; + va_start(args, message); + sentry__logs_log(SENTRY_LEVEL_DEBUG, message, args); + va_end(args); +} + +void +sentry_log_info(const char *message, ...) +{ + va_list args; + va_start(args, message); + sentry__logs_log(SENTRY_LEVEL_INFO, message, args); + va_end(args); +} + +void +sentry_log_warn(const char *message, ...) +{ + va_list args; + va_start(args, message); + sentry__logs_log(SENTRY_LEVEL_WARNING, message, args); + va_end(args); +} + +void +sentry_log_error(const char *message, ...) +{ + va_list args; + va_start(args, message); + sentry__logs_log(SENTRY_LEVEL_ERROR, message, args); + va_end(args); +} + +void +sentry_log_fatal(const char *message, ...) +{ + va_list args; + va_start(args, message); + sentry__logs_log(SENTRY_LEVEL_FATAL, message, args); + va_end(args); +} diff --git a/src/sentry_logs.h b/src/sentry_logs.h new file mode 100644 index 000000000..5fa6a4a77 --- /dev/null +++ b/src/sentry_logs.h @@ -0,0 +1,8 @@ +#ifndef SENTRY_LOGS_H_INCLUDED +#define SENTRY_LOGS_H_INCLUDED + +#include "sentry_boot.h" + +void sentry__logs_log(sentry_level_t level, const char *message, va_list args); + +#endif diff --git a/src/sentry_string.h b/src/sentry_string.h index 6b98c5766..48fa86f97 100644 --- a/src/sentry_string.h +++ b/src/sentry_string.h @@ -193,6 +193,17 @@ sentry__int64_to_string(int64_t val) return sentry__string_clone(buf); } +/** + * Converts an uint64_t into a string. + */ +static inline char * +sentry__uint64_to_string(uint64_t val) +{ + char buf[24]; + snprintf(buf, sizeof(buf), "%" PRIu64, val); + return sentry__string_clone(buf); +} + #ifdef SENTRY_PLATFORM_WINDOWS /** * Create a utf-8 string from a Wide String. diff --git a/src/sentry_value.c b/src/sentry_value.c index 9e573fe6f..d353573d0 100644 --- a/src/sentry_value.c +++ b/src/sentry_value.c @@ -73,6 +73,8 @@ #define THING_TYPE_OBJECT 1 #define THING_TYPE_STRING 2 #define THING_TYPE_DOUBLE 3 +#define THING_TYPE_INT64 4 +#define THING_TYPE_UINT64 5 /* internal value helpers */ @@ -80,6 +82,8 @@ typedef struct { union { void *_ptr; double _double; + int64_t _i64; + uint64_t _u64; } payload; long refcount; uint8_t type; @@ -106,6 +110,8 @@ static const char * level_as_string(sentry_level_t level) { switch (level) { + case SENTRY_LEVEL_TRACE: + return "trace"; case SENTRY_LEVEL_DEBUG: return "debug"; case SENTRY_LEVEL_WARNING: @@ -311,7 +317,7 @@ sentry_value_new_int32(int32_t value) sentry_value_t sentry_value_new_double(double value) { - thing_t *thing = sentry_malloc(sizeof(thing_t)); + thing_t *thing = SENTRY_MAKE(thing_t); if (!thing) { return sentry_value_new_null(); } @@ -324,6 +330,38 @@ sentry_value_new_double(double value) return rv; } +sentry_value_t +sentry_value_new_int64(int64_t value) +{ + thing_t *thing = SENTRY_MAKE(thing_t); + if (!thing) { + return sentry_value_new_null(); + } + thing->payload._i64 = value; + thing->refcount = 1; + thing->type = (uint8_t)(THING_TYPE_INT64 | THING_TYPE_FROZEN); + + sentry_value_t rv; + rv._bits = (uint64_t)(size_t)thing; + return rv; +} + +sentry_value_t +sentry_value_new_uint64(uint64_t value) +{ + thing_t *thing = SENTRY_MAKE(thing_t); + if (!thing) { + return sentry_value_new_null(); + } + thing->payload._u64 = value; + thing->refcount = 1; + thing->type = (uint8_t)(THING_TYPE_UINT64 | THING_TYPE_FROZEN); + + sentry_value_t rv; + rv._bits = (uint64_t)(size_t)thing; + return rv; +} + sentry_value_t sentry_value_new_bool(int value) { @@ -488,6 +526,10 @@ sentry_value_get_type(sentry_value_t value) return SENTRY_VALUE_TYPE_OBJECT; case THING_TYPE_DOUBLE: return SENTRY_VALUE_TYPE_DOUBLE; + case THING_TYPE_INT64: + return SENTRY_VALUE_TYPE_INT64; + case THING_TYPE_UINT64: + return SENTRY_VALUE_TYPE_UINT64; } UNREACHABLE("invalid thing type"); } else if ((value._bits & TAG_MASK) == TAG_CONST) { @@ -624,6 +666,21 @@ sentry__value_as_uuid(sentry_value_t value) char * sentry__value_stringify(sentry_value_t value) { + // returns empty string if snprintf fails + // (returning -1, so casting this to size_t it becomes > the buffer size) + // or if the value is too large for the buffer +#define STRINGIFY_NUMERIC(fmt, value_fn) \ + do { \ + char buf[24]; \ + size_t written \ + = (size_t)sentry__snprintf_c(buf, sizeof(buf), fmt, value_fn); \ + if (written >= sizeof(buf)) { \ + return sentry__string_clone(""); \ + } \ + buf[written] = '\0'; \ + return sentry__string_clone(buf); \ + } while (0) + switch (sentry_value_get_type(value)) { case SENTRY_VALUE_TYPE_LIST: case SENTRY_VALUE_TYPE_OBJECT: @@ -634,19 +691,17 @@ sentry__value_stringify(sentry_value_t value) sentry_value_is_true(value) ? "true" : "false"); case SENTRY_VALUE_TYPE_STRING: return sentry__string_clone(sentry_value_as_string(value)); + case SENTRY_VALUE_TYPE_INT64: + STRINGIFY_NUMERIC("%" PRIi64, sentry_value_as_int64(value)); + case SENTRY_VALUE_TYPE_UINT64: + STRINGIFY_NUMERIC("%" PRIi64, sentry_value_as_uint64(value)); case SENTRY_VALUE_TYPE_INT32: case SENTRY_VALUE_TYPE_DOUBLE: - default: { - char buf[24]; - size_t written = (size_t)sentry__snprintf_c( - buf, sizeof(buf), "%g", sentry_value_as_double(value)); - if (written >= sizeof(buf)) { - return sentry__string_clone(""); - } - buf[written] = '\0'; - return sentry__string_clone(buf); - } + default: + STRINGIFY_NUMERIC("%g", sentry_value_as_double(value)); } + +#undef STRINGIFY_NUMERIC } sentry_value_t @@ -677,6 +732,8 @@ sentry__value_clone(sentry_value_t value) } case THING_TYPE_STRING: case THING_TYPE_DOUBLE: + case THING_TYPE_INT64: + case THING_TYPE_UINT64: sentry_value_incref(value); return value; default: @@ -871,9 +928,18 @@ sentry_value_as_int32(sentry_value_t value) { if ((value._bits & TAG_MASK) == TAG_INT32) { return (int32_t)((int64_t)value._bits >> 32); - } else { - return 0; } + const thing_t *thing = value_as_thing(value); + if (thing && thing_get_type(thing) == THING_TYPE_INT64) { + SENTRY_WARN("Cannot convert int64 into int32, returning 0"); + } + if (thing && thing_get_type(thing) == THING_TYPE_UINT64) { + SENTRY_WARN("Cannot convert uint64 into int32, returning 0"); + } + if (thing && thing_get_type(thing) == THING_TYPE_DOUBLE) { + SENTRY_WARN("Cannot convert double into int32, returning 0"); + } + return 0; } double @@ -886,9 +952,56 @@ sentry_value_as_double(sentry_value_t value) const thing_t *thing = value_as_thing(value); if (thing && thing_get_type(thing) == THING_TYPE_DOUBLE) { return thing->payload._double; - } else { - return (double)NAN; } + if (thing && thing_get_type(thing) == THING_TYPE_INT64) { + SENTRY_WARN("Cannot convert int64 into double, returning NAN"); + } + if (thing && thing_get_type(thing) == THING_TYPE_UINT64) { + SENTRY_WARN("Cannot convert uint64 into double, returning NAN"); + } + + return (double)NAN; +} + +int64_t +sentry_value_as_int64(sentry_value_t value) +{ + if ((value._bits & TAG_MASK) == TAG_INT32) { + return (int64_t)sentry_value_as_int32(value); + } + + const thing_t *thing = value_as_thing(value); + if (thing && thing_get_type(thing) == THING_TYPE_INT64) { + return thing->payload._i64; + } + if (thing && thing_get_type(thing) == THING_TYPE_UINT64) { + SENTRY_WARN("Cannot convert uint64 into int64, returning 0"); + } + if (thing && thing_get_type(thing) == THING_TYPE_DOUBLE) { + SENTRY_WARN("Cannot convert double into int64, returning 0"); + } + return 0; +} + +uint64_t +sentry_value_as_uint64(sentry_value_t value) +{ + if ((value._bits & TAG_MASK) == TAG_INT32) { + SENTRY_WARN("Cannot convert int32 into uint64, returning 0"); + return 0; + } + + const thing_t *thing = value_as_thing(value); + if (thing && thing_get_type(thing) == THING_TYPE_UINT64) { + return thing->payload._u64; + } + if (thing && thing_get_type(thing) == THING_TYPE_INT64) { + SENTRY_WARN("Cannot convert int64 into uint64, returning 0"); + } + if (thing && thing_get_type(thing) == THING_TYPE_DOUBLE) { + SENTRY_WARN("Cannot convert int64 into uint64, returning 0"); + } + return 0; } const char * @@ -897,9 +1010,8 @@ sentry_value_as_string(sentry_value_t value) const thing_t *thing = value_as_thing(value); if (thing && thing_get_type(thing) == THING_TYPE_STRING) { return (const char *)thing->payload._ptr; - } else { - return ""; } + return ""; } sentry_value_t @@ -936,6 +1048,10 @@ sentry_value_is_true(sentry_value_t value) return 0; case SENTRY_VALUE_TYPE_INT32: return sentry_value_as_int32(value) != 0; + case SENTRY_VALUE_TYPE_INT64: + return sentry_value_as_int64(value) != 0; + case SENTRY_VALUE_TYPE_UINT64: + return sentry_value_as_uint64(value) != 0; case SENTRY_VALUE_TYPE_DOUBLE: return sentry_value_as_double(value) != 0.0; case SENTRY_VALUE_TYPE_STRING: @@ -1000,6 +1116,12 @@ sentry__jsonwriter_write_value(sentry_jsonwriter_t *jw, sentry_value_t value) case SENTRY_VALUE_TYPE_INT32: sentry__jsonwriter_write_int32(jw, sentry_value_as_int32(value)); break; + case SENTRY_VALUE_TYPE_INT64: + sentry__jsonwriter_write_int64(jw, sentry_value_as_int64(value)); + break; + case SENTRY_VALUE_TYPE_UINT64: + sentry__jsonwriter_write_uint64(jw, sentry_value_as_uint64(value)); + break; case SENTRY_VALUE_TYPE_DOUBLE: sentry__jsonwriter_write_double(jw, sentry_value_as_double(value)); break; @@ -1052,6 +1174,12 @@ value_to_msgpack(mpack_writer_t *writer, sentry_value_t value) case SENTRY_VALUE_TYPE_INT32: mpack_write_i32(writer, sentry_value_as_int32(value)); break; + case SENTRY_VALUE_TYPE_INT64: + mpack_write_i64(writer, sentry_value_as_int64(value)); + break; + case SENTRY_VALUE_TYPE_UINT64: + mpack_write_u64(writer, sentry_value_as_uint64(value)); + break; case SENTRY_VALUE_TYPE_DOUBLE: mpack_write_double(writer, sentry_value_as_double(value)); break; diff --git a/tests/unit/CMakeLists.txt b/tests/unit/CMakeLists.txt index 23038f408..1c17257b5 100644 --- a/tests/unit/CMakeLists.txt +++ b/tests/unit/CMakeLists.txt @@ -28,6 +28,7 @@ add_executable(sentry_test_unit test_fuzzfailures.c test_info.c test_logger.c + test_logs.c test_modulefinder.c test_mpack.c test_options.c diff --git a/tests/unit/test_logger.c b/tests/unit/test_logger.c index 89e50553e..ff0a784a2 100644 --- a/tests/unit/test_logger.c +++ b/tests/unit/test_logger.c @@ -51,3 +51,69 @@ SENTRY_TEST(custom_logger) sentry_close(); } } + +static void +test_log_level( + sentry_level_t level, const char *message, va_list args, void *_data) +{ + (void)level; + (void)message; + (void)args; + + logger_test_t *data = _data; + if (data->assert_now) { + data->called += 1; + } +} + +SENTRY_TEST(logger_level) +{ + // Test structure: for each level, test that only messages >= that level are + // logged + const struct { + sentry_level_t level; + int expected_count; // How many of the 5 test messages should be logged + } test_cases[] = { + { SENTRY_LEVEL_TRACE, + 5 }, // All messages: TRACE, DEBUG, INFO, WARN, ERROR + { SENTRY_LEVEL_DEBUG, + 4 }, // DEBUG, INFO, WARN, ERROR (TRACE filtered out) + { SENTRY_LEVEL_INFO, 3 }, // INFO, WARN, ERROR + { SENTRY_LEVEL_WARNING, 2 }, // WARN, ERROR + { SENTRY_LEVEL_ERROR, 1 }, // ERROR only + }; + + for (size_t i = 0; i < 5; i++) { // for each of the 5 logger levels + logger_test_t data = { 0, false }; + + { + SENTRY_TEST_OPTIONS_NEW(options); + sentry_options_set_debug(options, true); + sentry_options_set_logger_level(options, test_cases[i].level); + sentry_options_set_logger(options, test_log_level, &data); + + sentry_init(options); + + data.assert_now = true; + // Test all 5 levels in order from most to least verbose + SENTRY_TRACE("Logging Trace"); // level -2 + SENTRY_DEBUG("Logging Debug"); // level -1 + SENTRY_INFO("Logging Info"); // level 0 + SENTRY_WARN("Logging Warning"); // level 1 + SENTRY_ERROR("Logging Error"); // level 2 + + data.assert_now = false; + + TEST_CHECK_INT_EQUAL(data.called, test_cases[i].expected_count); + + sentry_close(); + } + + { + // *really* clear the logger instance + SENTRY_TEST_OPTIONS_NEW(options); + sentry_init(options); + sentry_close(); + } + } +} diff --git a/tests/unit/test_logs.c b/tests/unit/test_logs.c new file mode 100644 index 000000000..4ad2b4049 --- /dev/null +++ b/tests/unit/test_logs.c @@ -0,0 +1,100 @@ +#include "sentry_logs.h" +#include "sentry_testsupport.h" + +#include "sentry_envelope.h" + +// TODO these tests will need updating after batching is implemented + +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 + 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"); + + sentry_envelope_free(envelope); +} + +SENTRY_TEST(basic_logging_functionality) +{ + uint64_t called_transport = 0; + + SENTRY_TEST_OPTIONS_NEW(options); + sentry_options_set_dsn(options, "https://foo@sentry.invalid/42"); + sentry_options_set_enable_logs(options, true); + + sentry_transport_t *transport + = sentry_transport_new(validate_logs_envelope); + sentry_transport_set_state(transport, &called_transport); + sentry_options_set_transport(options, transport); + + sentry_init(options); + + // 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"); + sentry_log_fatal("Fatal message"); + + sentry_close(); + + TEST_CHECK_INT_EQUAL(called_transport, 6); +} + +SENTRY_TEST(logs_disabled_by_default) +{ + uint64_t called_transport = 0; + + SENTRY_TEST_OPTIONS_NEW(options); + sentry_options_set_dsn(options, "https://foo@sentry.invalid/42"); + + sentry_transport_t *transport + = sentry_transport_new(validate_logs_envelope); + sentry_transport_set_state(transport, &called_transport); + sentry_options_set_transport(options, transport); + + // Don't explicitly enable logs - they should be disabled by default + sentry_init(options); + + sentry_log_info("This should not be sent"); + + sentry_close(); + + // Transport should not be called since logs are disabled + TEST_CHECK_INT_EQUAL(called_transport, 0); +} + +SENTRY_TEST(formatted_log_messages) +{ + uint64_t called_transport = 0; + + SENTRY_TEST_OPTIONS_NEW(options); + sentry_options_set_dsn(options, "https://foo@sentry.invalid/42"); + sentry_options_set_enable_logs(options, true); + + sentry_transport_t *transport + = sentry_transport_new(validate_logs_envelope); + sentry_transport_set_state(transport, &called_transport); + sentry_options_set_transport(options, transport); + + sentry_init(options); + + // Test format specifiers + 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_close(); + + // Transport should be called three times + TEST_CHECK_INT_EQUAL(called_transport, 3); +} diff --git a/tests/unit/test_value.c b/tests/unit/test_value.c index 40d0a2ae5..18457c93b 100644 --- a/tests/unit/test_value.c +++ b/tests/unit/test_value.c @@ -71,6 +71,112 @@ SENTRY_TEST(value_int32) TEST_CHECK(sentry_value_refcount(val) == 1); } +SENTRY_TEST(value_int64) +{ + sentry_value_t val = sentry_value_new_int64(42LL); + TEST_CHECK(sentry_value_get_type(val) == SENTRY_VALUE_TYPE_INT64); + TEST_CHECK(sentry_value_as_int64(val) == 42LL); + // We don't convert int64 to double + TEST_CHECK(isnan(sentry_value_as_double(val))); + // We don't convert int64 to int32 + TEST_CHECK(sentry_value_as_int32(val) == 0); + TEST_CHECK(sentry_value_is_true(val)); + TEST_CHECK_JSON_VALUE(val, "42"); + TEST_CHECK(sentry_value_refcount(val) == 1); + TEST_CHECK(sentry_value_is_frozen(val)); + sentry_value_decref(val); + + // Test large positive value + val = sentry_value_new_int64(INT64_MAX); + TEST_CHECK(sentry_value_get_type(val) == SENTRY_VALUE_TYPE_INT64); + TEST_CHECK(sentry_value_as_int64(val) == INT64_MAX); + TEST_CHECK(sentry_value_is_true(val)); + TEST_CHECK_JSON_VALUE(val, "9223372036854775807"); + sentry_value_decref(val); + + // Test large negative value + val = sentry_value_new_int64(INT64_MIN); + TEST_CHECK(sentry_value_get_type(val) == SENTRY_VALUE_TYPE_INT64); + TEST_CHECK(sentry_value_as_int64(val) == INT64_MIN); + TEST_CHECK(sentry_value_is_true(val)); + TEST_CHECK_JSON_VALUE(val, "-9223372036854775808"); + sentry_value_decref(val); + + // Test zero + val = sentry_value_new_int64(0LL); + TEST_CHECK(sentry_value_get_type(val) == SENTRY_VALUE_TYPE_INT64); + TEST_CHECK(sentry_value_as_int64(val) == 0LL); + TEST_CHECK(!sentry_value_is_true(val)); + TEST_CHECK_JSON_VALUE(val, "0"); + TEST_CHECK(sentry_value_refcount(val) == 1); + TEST_CHECK(sentry_value_is_frozen(val)); + sentry_value_decref(val); + + // We do convert int32 to int64 + val = sentry_value_new_int32(42); + TEST_CHECK(sentry_value_as_int64(val) == 42LL); + sentry_value_decref(val); + + // We don't convert uint64 to int64 + val = sentry_value_new_uint64(-42LL); + TEST_CHECK(sentry_value_as_int64(val) == 0); + sentry_value_decref(val); + + // We don't convert double to int64 + val = sentry_value_new_double(42.99); + TEST_CHECK(sentry_value_as_int64(val) == 0); + sentry_value_decref(val); +} + +SENTRY_TEST(value_uint64) +{ + sentry_value_t val = sentry_value_new_uint64(42ULL); + TEST_CHECK(sentry_value_get_type(val) == SENTRY_VALUE_TYPE_UINT64); + TEST_CHECK(sentry_value_as_uint64(val) == 42ULL); + // We don't convert uint64 to double + TEST_CHECK(isnan(sentry_value_as_double(val))); + // We don't convert uint64 to int32 + TEST_CHECK(sentry_value_as_int32(val) == 0); + TEST_CHECK(sentry_value_is_true(val)); + TEST_CHECK_JSON_VALUE(val, "42"); + TEST_CHECK(sentry_value_refcount(val) == 1); + TEST_CHECK(sentry_value_is_frozen(val)); + sentry_value_decref(val); + + // Test large positive value + val = sentry_value_new_uint64(UINT64_MAX); + TEST_CHECK(sentry_value_get_type(val) == SENTRY_VALUE_TYPE_UINT64); + TEST_CHECK(sentry_value_as_uint64(val) == UINT64_MAX); + TEST_CHECK(sentry_value_is_true(val)); + TEST_CHECK_JSON_VALUE(val, "18446744073709551615"); + sentry_value_decref(val); + + // Test zero + val = sentry_value_new_uint64(0ULL); + TEST_CHECK(sentry_value_get_type(val) == SENTRY_VALUE_TYPE_UINT64); + TEST_CHECK(sentry_value_as_uint64(val) == 0ULL); + TEST_CHECK(!sentry_value_is_true(val)); + TEST_CHECK_JSON_VALUE(val, "0"); + TEST_CHECK(sentry_value_refcount(val) == 1); + TEST_CHECK(sentry_value_is_frozen(val)); + sentry_value_decref(val); + + // We don't convert int32 to uint64 + val = sentry_value_new_int32(42); + TEST_CHECK(sentry_value_as_uint64(val) == 0); + sentry_value_decref(val); + + // We don't convert double to uint64 + val = sentry_value_new_double(123.456); + TEST_CHECK(sentry_value_as_uint64(val) == 0); + sentry_value_decref(val); + + // We don't convert int64 to uint64 + val = sentry_value_new_int64(42LL); + TEST_CHECK(sentry_value_as_uint64(val) == 0); + sentry_value_decref(val); +} + SENTRY_TEST(value_double) { sentry_value_t val = sentry_value_new_double(42.05); @@ -452,7 +558,7 @@ SENTRY_TEST(value_json_parsing) "\"surrogates\":\"𐐷\"}"); sentry_value_decref(rv); - // unmatched surrogates don’t parse + // unmatched surrogates don't parse rv = sentry__value_from_json(STRING("\"\\uD801\"")); TEST_CHECK(sentry_value_is_null(rv)); rv = sentry__value_from_json( @@ -521,7 +627,7 @@ SENTRY_TEST(value_json_surrogates) TEST_CHECK_JSON_VALUE(rv, "{\"surrogates\":\"oh 𐐷 hi\"}"); sentry_value_decref(rv); - // unmatched surrogates don’t parse + // unmatched surrogates don't parse rv = sentry__value_from_json(STRING("\"\\uD801\"")); TEST_CHECK(sentry_value_is_null(rv)); rv = sentry__value_from_json( diff --git a/tests/unit/tests.inc b/tests/unit/tests.inc index 048f554c5..c836832b3 100644 --- a/tests/unit/tests.inc +++ b/tests/unit/tests.inc @@ -11,6 +11,7 @@ XX(basic_http_request_preparation_for_event_with_attachment) XX(basic_http_request_preparation_for_minidump) XX(basic_http_request_preparation_for_transaction) XX(basic_http_request_preparation_for_user_feedback) +XX(basic_logging_functionality) XX(basic_spans) XX(basic_tracing_context) XX(basic_transaction) @@ -51,6 +52,7 @@ XX(dsn_without_project_id_is_invalid) XX(dsn_without_url_scheme_is_invalid) XX(empty_transport) XX(exception_without_type_or_value_still_valid) +XX(formatted_log_messages) XX(fuzz_json) XX(init_failure) XX(internal_uuid_api) @@ -58,6 +60,8 @@ XX(invalid_dsn) XX(invalid_proxy) XX(iso_time) XX(lazy_attachments) +XX(logger_level) +XX(logs_disabled_by_default) XX(message_with_null_text_is_valid) XX(module_addr) XX(module_finder) @@ -145,6 +149,7 @@ XX(value_double) XX(value_freezing) XX(value_get_by_null_key) XX(value_int32) +XX(value_int64) XX(value_json_deeply_nested) XX(value_json_escaping) XX(value_json_invalid_doubles) @@ -162,6 +167,7 @@ XX(value_set_by_null_key) XX(value_set_stacktrace) XX(value_string) XX(value_string_n) +XX(value_uint64) XX(value_unicode) XX(value_user) XX(value_wrong_type) From ad7694b8078b45fb9af16158d30b63f71f2e07b6 Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Thu, 31 Jul 2025 14:14:29 +0200 Subject: [PATCH 04/14] fixed log parameter conversion --- examples/example.c | 6 ++++++ src/sentry_logs.c | 11 ++++++----- 2 files changed, 12 insertions(+), 5 deletions(-) diff --git a/examples/example.c b/examples/example.c index 774445ff7..0db09aa16 100644 --- a/examples/example.c +++ b/examples/example.c @@ -395,6 +395,12 @@ 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, (uint64_t)18446744073709551615); + sentry_log_warn("This is a medium number as unsigned %" PRIu64, + (uint64_t)9007199254740991); + sentry_log_warn("This is a medium number as signed %" PRId64, + (int64_t)9007199254740991); 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"); diff --git a/src/sentry_logs.c b/src/sentry_logs.c index 9f87e3bd9..319be0717 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -36,7 +36,7 @@ construct_param_from_conversion(const char conversion, va_list *args_copy) switch (conversion) { case 'd': case 'i': { - int val = va_arg(*args_copy, int); + long long val = va_arg(*args_copy, long long); sentry_value_set_by_key( param_obj, "value", sentry_value_new_int64(val)); sentry_value_set_by_key( @@ -47,9 +47,10 @@ construct_param_from_conversion(const char conversion, va_list *args_copy) case 'x': case 'X': case 'o': { - unsigned int val = va_arg(*args_copy, unsigned int); - sentry_value_set_by_key(param_obj, "value", - sentry__value_new_string_owned(sentry__uint64_to_string(val))); + unsigned long long int val = va_arg(*args_copy, unsigned long long int); + sentry_value_set_by_key( + param_obj, "value", sentry_value_new_uint64(val)); + // TODO update once unsigned 64-bit can be sent sentry_value_set_by_key( param_obj, "type", sentry_value_new_string("string")); break; @@ -356,7 +357,7 @@ sentry__logs_log(sentry_level_t level, const char *message, va_list args) 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_envelope_write_to_file(envelope, "logs_envelope.json"); SENTRY_WITH_OPTIONS (options) { sentry__capture_envelope(options->transport, envelope); } From 8f0fa12079ed184a6e792deb7f71df9d97d416f5 Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Thu, 31 Jul 2025 15:56:22 +0200 Subject: [PATCH 05/14] update example to avoid warning-as-error --- examples/example.c | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/examples/example.c b/examples/example.c index 0db09aa16..68ed11f9c 100644 --- a/examples/example.c +++ b/examples/example.c @@ -396,11 +396,11 @@ 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, (uint64_t)18446744073709551615); + "This is a big number %" PRIu64, 18446744073709551615ULL); sentry_log_warn("This is a medium number as unsigned %" PRIu64, - (uint64_t)9007199254740991); - sentry_log_warn("This is a medium number as signed %" PRId64, - (int64_t)9007199254740991); + 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"); From fbed0e2b0aeec780d82d2a3eee72d6c672b0939c Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Fri, 8 Aug 2025 13:16:48 +0200 Subject: [PATCH 06/14] initial queue attempt --- src/sentry_logs.c | 70 +++++++++++++++++++++++++++++++++++------------ 1 file changed, 52 insertions(+), 18 deletions(-) diff --git a/src/sentry_logs.c b/src/sentry_logs.c index 319be0717..e612c6242 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -4,10 +4,61 @@ #include "sentry_options.h" #include "sentry_os.h" #include "sentry_scope.h" +#include "sentry_sync.h" #include #include +const int QUEUE_LENGTH = 10; + +struct logs_queue { + sentry_value_t queue[QUEUE_LENGTH]; // could just be sentry_value_t list? + long index; + long adding; +} typedef LogQueue; + +LogQueue lq; + +static void +flush_logs() +{ + sentry_value_t logs = sentry_value_new_object(); + sentry_value_t logs_list = sentry_value_new_list(); + for (int i = 0; i < QUEUE_LENGTH; i++) { + sentry_value_append(logs_list, lq.queue[i]); + } + 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); + } + // free the logs object since envelope doesn't take + sentry_value_decref(logs); + sentry__atomic_store(&lq.index, 0); +} + +static bool +enqueu_log(sentry_value_t log) +{ + // atomically fetch index and add one + long log_idx = sentry__atomic_fetch_and_add(&lq.index, 1); + sentry__atomic_fetch_and_add(&lq.adding, 1); + if (log_idx >= 100) { // already flushing + // TODO send client report? + SENTRY_WARN("Losing log"); + return false; + } + lq.queue[log_idx] = log; + if (log_idx == QUEUE_LENGTH - 1) { + flush_logs(); + } + sentry__atomic_fetch_and_add(&lq.adding, -1); +} + static const char * level_as_string(sentry_level_t level) { @@ -346,24 +397,7 @@ sentry__logs_log(sentry_level_t level, const char *message, va_list args) if (enable_logs) { // 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); - } - // For now, free the logs object since envelope doesn't take - // ownership - sentry_value_decref(logs); + enqueu_log(log); } } From 234bbb6024438280d6797616c75f08461ea20603 Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Fri, 8 Aug 2025 13:41:29 +0200 Subject: [PATCH 07/14] add timer --- src/sentry_envelope.c | 3 +- src/sentry_logs.c | 75 +++++++++++++++++++++++++++++++++++++++---- 2 files changed, 71 insertions(+), 7 deletions(-) diff --git a/src/sentry_envelope.c b/src/sentry_envelope.c index 9cf3305fe..23852485c 100644 --- a/src/sentry_envelope.c +++ b/src/sentry_envelope.c @@ -420,7 +420,8 @@ 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")); diff --git a/src/sentry_logs.c b/src/sentry_logs.c index e612c6242..b4a877da8 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -8,23 +8,39 @@ #include #include +#include -const int QUEUE_LENGTH = 10; +const int QUEUE_LENGTH = 100; +const int FLUSH_TIMER = 5; struct logs_queue { - sentry_value_t queue[QUEUE_LENGTH]; // could just be sentry_value_t list? + sentry_value_t + queue[QUEUE_LENGTH]; // TODO could this be sentry_value_t list? long index; long adding; + long timer_running; // atomic flag: 1 if timer thread is active, 0 otherwise + long flushing; // atomic flag: 1 if currently flushing, 0 otherwise } typedef LogQueue; LogQueue lq; +// Forward declaration for timer thread function +SENTRY_THREAD_FN timer_thread_func(void *arg); + static void -flush_logs() +flush_logs(void) { + // Use atomic fetch and add to ensure only one thread flushes at a time + long was_flushing = sentry__atomic_fetch_and_add(&lq.flushing, 1); + if (was_flushing != 0) { + // Another thread is already flushing, decrement and return + sentry__atomic_fetch_and_add(&lq.flushing, -1); + return; + } + sentry_value_t logs = sentry_value_new_object(); sentry_value_t logs_list = sentry_value_new_list(); - for (int i = 0; i < QUEUE_LENGTH; i++) { + for (int i = 0; i < sentry__atomic_fetch(&lq.index); i++) { sentry_value_append(logs_list, lq.queue[i]); } sentry_value_set_by_key(logs, "items", logs_list); @@ -32,13 +48,16 @@ flush_logs() 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_envelope_write_to_file(envelope, "logs_envelope.json"); SENTRY_WITH_OPTIONS (options) { sentry__capture_envelope(options->transport, envelope); } // free the logs object since envelope doesn't take sentry_value_decref(logs); sentry__atomic_store(&lq.index, 0); + + // Clear flushing flag + sentry__atomic_fetch_and_add(&lq.flushing, -1); } static bool @@ -47,7 +66,7 @@ enqueu_log(sentry_value_t log) // atomically fetch index and add one long log_idx = sentry__atomic_fetch_and_add(&lq.index, 1); sentry__atomic_fetch_and_add(&lq.adding, 1); - if (log_idx >= 100) { // already flushing + if (log_idx >= QUEUE_LENGTH) { // already flushing // TODO send client report? SENTRY_WARN("Losing log"); return false; @@ -57,6 +76,50 @@ enqueu_log(sentry_value_t log) flush_logs(); } sentry__atomic_fetch_and_add(&lq.adding, -1); + + // Start timer thread if this is the first log and timer is not already + // running + if (log_idx == 0) { + long was_running = sentry__atomic_fetch_and_add(&lq.timer_running, 1); + if (was_running == 0) { + // We're the first to set the timer, spawn the thread + sentry_threadid_t timer_thread; + sentry__thread_init(&timer_thread); + if (sentry__thread_spawn(&timer_thread, timer_thread_func, NULL) + != 0) { + SENTRY_WARN("Failed to spawn timer thread"); + sentry__atomic_fetch_and_add(&lq.timer_running, -1); + } else { + sentry__thread_detach(timer_thread); + } + } else { + // Timer was already running, decrement back + sentry__atomic_fetch_and_add(&lq.timer_running, -1); + } + } + + return true; +} + +SENTRY_THREAD_FN +timer_thread_func(void *arg) +{ + (void)arg; // unused parameter + + // Sleep for 5 seconds +#ifdef SENTRY_PLATFORM_WINDOWS + Sleep(FLUSH_TIMER * 1000); +#else + sleep(FLUSH_TIMER); +#endif + + // Try to flush logs + flush_logs(); + + // Reset timer state - decrement the counter + sentry__atomic_fetch_and_add(&lq.timer_running, -1); + + return 0; } static const char * From 5815c1ea914e61477fe53a13674994401ee20650 Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Fri, 8 Aug 2025 15:20:18 +0200 Subject: [PATCH 08/14] prototype double buffer approach --- src/sentry_logs.c | 183 +++++++++++++++++++++++++++++++++------------- 1 file changed, 131 insertions(+), 52 deletions(-) diff --git a/src/sentry_logs.c b/src/sentry_logs.c index b4a877da8..744a85af9 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -10,19 +10,27 @@ #include #include -const int QUEUE_LENGTH = 100; -const int FLUSH_TIMER = 5; +#define QUEUE_LENGTH 100 +#define FLUSH_TIMER 5 + +typedef struct { + sentry_value_t logs[QUEUE_LENGTH]; + volatile long count; // Number of logs in this buffer +} log_buffer_t; struct logs_queue { - sentry_value_t - queue[QUEUE_LENGTH]; // TODO could this be sentry_value_t list? - long index; - long adding; - long timer_running; // atomic flag: 1 if timer thread is active, 0 otherwise - long flushing; // atomic flag: 1 if currently flushing, 0 otherwise + log_buffer_t buffers[2]; // Double buffer + volatile long + active_buffer; // 0 or 1 - which buffer is currently active for writing + volatile long + timer_running; // atomic flag: 1 if timer thread is active, 0 otherwise + volatile long flushing; // atomic flag: 1 if currently flushing, 0 otherwise } typedef LogQueue; -LogQueue lq; +LogQueue lq = { .buffers = { { .count = 0 }, { .count = 0 } }, + .active_buffer = 0, + .timer_running = 0, + .flushing = 0 }; // Forward declaration for timer thread function SENTRY_THREAD_FN timer_thread_func(void *arg); @@ -30,21 +38,54 @@ SENTRY_THREAD_FN timer_thread_func(void *arg); static void flush_logs(void) { - // Use atomic fetch and add to ensure only one thread flushes at a time - long was_flushing = sentry__atomic_fetch_and_add(&lq.flushing, 1); - if (was_flushing != 0) { - // Another thread is already flushing, decrement and return - sentry__atomic_fetch_and_add(&lq.flushing, -1); + // Use atomic compare-and-swap to ensure only one thread flushes at a time + long expected = 0; + // TODO platform-agnostic? + if (!__sync_bool_compare_and_swap(&lq.flushing, expected, 1)) { + // Another thread is already flushing return; } + // Determine which buffer to flush + long current_active = sentry__atomic_fetch(&lq.active_buffer); + long flush_buffer_idx + = current_active; // Start by trying to flush the active buffer + + // Check if active buffer has any logs to flush + if (sentry__atomic_fetch(&lq.buffers[current_active].count) == 0) { + // Active buffer is empty, try the other buffer + flush_buffer_idx = 1 - current_active; + if (sentry__atomic_fetch(&lq.buffers[flush_buffer_idx].count) == 0) { + // Both buffers are empty, nothing to flush + sentry__atomic_store(&lq.flushing, 0); + return; + } + } else { + // Active buffer has logs, switch to the other buffer for new writes + long new_active = 1 - current_active; + sentry__atomic_store(&lq.active_buffer, new_active); + } + + log_buffer_t *flush_buffer = &lq.buffers[flush_buffer_idx]; + long count = sentry__atomic_fetch(&flush_buffer->count); + + if (count == 0) { + // Buffer became empty while we were setting up, nothing to do + sentry__atomic_store(&lq.flushing, 0); + return; + } + + // Create envelope with logs from the buffer being flushed sentry_value_t logs = sentry_value_new_object(); sentry_value_t logs_list = sentry_value_new_list(); - for (int i = 0; i < sentry__atomic_fetch(&lq.index); i++) { - sentry_value_append(logs_list, lq.queue[i]); + + for (long i = 0; i < count; i++) { + sentry_value_append(logs_list, flush_buffer->logs[i]); } + sentry_value_set_by_key(logs, "items", logs_list); - // sending of the envelope + + // Send the envelope sentry_envelope_t *envelope = sentry__envelope_new(); sentry__envelope_add_logs(envelope, logs); // TODO remove debug write to file below @@ -52,53 +93,91 @@ flush_logs(void) SENTRY_WITH_OPTIONS (options) { sentry__capture_envelope(options->transport, envelope); } - // free the logs object since envelope doesn't take + + // Free the logs object since envelope doesn't take ownership sentry_value_decref(logs); - sentry__atomic_store(&lq.index, 0); + + // Reset the flushed buffer - this is now safe since we switched active + // buffer + sentry__atomic_store(&flush_buffer->count, 0); // Clear flushing flag - sentry__atomic_fetch_and_add(&lq.flushing, -1); + sentry__atomic_store(&lq.flushing, 0); } static bool enqueu_log(sentry_value_t log) { - // atomically fetch index and add one - long log_idx = sentry__atomic_fetch_and_add(&lq.index, 1); - sentry__atomic_fetch_and_add(&lq.adding, 1); - if (log_idx >= QUEUE_LENGTH) { // already flushing - // TODO send client report? - SENTRY_WARN("Losing log"); - return false; - } - lq.queue[log_idx] = log; - if (log_idx == QUEUE_LENGTH - 1) { - flush_logs(); - } - sentry__atomic_fetch_and_add(&lq.adding, -1); - - // Start timer thread if this is the first log and timer is not already - // running - if (log_idx == 0) { - long was_running = sentry__atomic_fetch_and_add(&lq.timer_running, 1); - if (was_running == 0) { - // We're the first to set the timer, spawn the thread - sentry_threadid_t timer_thread; - sentry__thread_init(&timer_thread); - if (sentry__thread_spawn(&timer_thread, timer_thread_func, NULL) - != 0) { - SENTRY_WARN("Failed to spawn timer thread"); - sentry__atomic_fetch_and_add(&lq.timer_running, -1); - } else { - sentry__thread_detach(timer_thread); + // Retry loop in case buffer switches during our attempt + for (int retry = 0; retry < 10; retry++) { + // Get current active buffer index + long buffer_idx = sentry__atomic_fetch(&lq.active_buffer); + log_buffer_t *current_buffer = &lq.buffers[buffer_idx]; + + // Try to get a slot in the current buffer + long log_idx = sentry__atomic_fetch_and_add(¤t_buffer->count, 1); + + if (log_idx < QUEUE_LENGTH) { + // Successfully got a slot, write the log + current_buffer->logs[log_idx] = log; + + // Check if this buffer is now full and trigger flush + if (log_idx == QUEUE_LENGTH - 1) { + flush_logs(); + } + + // Start timer thread if this is the first log in any buffer + bool should_start_timer = false; + if (log_idx == 0) { + // Check if the other buffer is also empty + long other_buffer_idx = 1 - buffer_idx; + if (sentry__atomic_fetch(&lq.buffers[other_buffer_idx].count) + == 0) { + should_start_timer = true; + } + } + + if (should_start_timer) { + long was_running + = sentry__atomic_fetch_and_add(&lq.timer_running, 1); + if (was_running == 0) { + // We're the first to set the timer, spawn the thread + sentry_threadid_t timer_thread; + sentry__thread_init(&timer_thread); + if (sentry__thread_spawn( + &timer_thread, timer_thread_func, NULL) + != 0) { + SENTRY_WARN("Failed to spawn timer thread"); + sentry__atomic_fetch_and_add(&lq.timer_running, -1); + } else { + sentry__thread_detach(timer_thread); + } + } else { + // Timer was already running, decrement back + sentry__atomic_fetch_and_add(&lq.timer_running, -1); + } } + + return true; } else { - // Timer was already running, decrement back - sentry__atomic_fetch_and_add(&lq.timer_running, -1); + // Buffer is full, roll back our increment + sentry__atomic_fetch_and_add(¤t_buffer->count, -1); + + // Try to trigger a flush to switch buffers + flush_logs(); + + // Brief pause before retry to allow flush to complete +#ifdef SENTRY_PLATFORM_WINDOWS + Sleep(1); +#else + usleep(1000); // 1ms +#endif } } - return true; + // All retries exhausted - both buffers are likely full + SENTRY_WARN("Unable to enqueue log - all buffers full"); + return false; } SENTRY_THREAD_FN @@ -113,7 +192,7 @@ timer_thread_func(void *arg) sleep(FLUSH_TIMER); #endif - // Try to flush logs + // Try to flush logs - this will flush whichever buffer has content flush_logs(); // Reset timer state - decrement the counter From 914514d43e445f7f6f79cef831a4754848284cfc Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Fri, 8 Aug 2025 15:32:28 +0200 Subject: [PATCH 09/14] update logs unit tests for batching --- src/sentry_logs.c | 7 ++++++- tests/unit/test_logs.c | 6 ++++-- 2 files changed, 10 insertions(+), 3 deletions(-) diff --git a/src/sentry_logs.c b/src/sentry_logs.c index 744a85af9..3253e4330 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -10,7 +10,12 @@ #include #include -#define QUEUE_LENGTH 100 +// TODO think about this +#ifdef SENTRY_UNITTEST +# define QUEUE_LENGTH 5 +#else +# define QUEUE_LENGTH 100 +#endif #define FLUSH_TIMER 5 typedef struct { diff --git a/tests/unit/test_logs.c b/tests/unit/test_logs.c index 4ad2b4049..2628516ce 100644 --- a/tests/unit/test_logs.c +++ b/tests/unit/test_logs.c @@ -47,7 +47,7 @@ SENTRY_TEST(basic_logging_functionality) sentry_close(); - TEST_CHECK_INT_EQUAL(called_transport, 6); + TEST_CHECK_INT_EQUAL(called_transport, 1); } SENTRY_TEST(logs_disabled_by_default) @@ -92,9 +92,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); + TEST_CHECK_INT_EQUAL(called_transport, 1); } From d1988a82f3b3bd90e7a1107c4ce2ef71f7139ce8 Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Mon, 11 Aug 2025 15:21:26 +0200 Subject: [PATCH 10/14] replace timer with bgworker --- src/sentry_core.c | 4 ++ src/sentry_logs.c | 119 +++++++++++++++++++++++++++++++++++++--------- src/sentry_logs.h | 7 +++ 3 files changed, 108 insertions(+), 22 deletions(-) diff --git a/src/sentry_core.c b/src/sentry_core.c index 12c7f88f7..20230f4b2 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" @@ -324,6 +325,9 @@ sentry_close(void) options->backend->shutdown_func(options->backend); } + // Shutdown logs system before transport to ensure logs are flushed + sentry__logs_shutdown(options->shutdown_timeout); + if (options->transport) { if (sentry__transport_shutdown( options->transport, options->shutdown_timeout) diff --git a/src/sentry_logs.c b/src/sentry_logs.c index 3253e4330..79126f183 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -32,13 +32,24 @@ struct logs_queue { volatile long flushing; // atomic flag: 1 if currently flushing, 0 otherwise } typedef LogQueue; -LogQueue lq = { .buffers = { { .count = 0 }, { .count = 0 } }, - .active_buffer = 0, - .timer_running = 0, - .flushing = 0 }; +// Global logs state including bgworker for timer management +static struct { + LogQueue queue; + sentry_bgworker_t *timer_worker; + volatile long + timer_task_submitted; // 1 if timer task is submitted, 0 otherwise +} g_logs_state = { .queue = { .buffers = { { .count = 0 }, { .count = 0 } }, + .active_buffer = 0, + .timer_running = 0, + .flushing = 0 }, + .timer_worker = NULL, + .timer_task_submitted = 0 }; + +// Convenience macro to access the queue +#define lq g_logs_state.queue -// Forward declaration for timer thread function -SENTRY_THREAD_FN timer_thread_func(void *arg); +// Forward declaration for timer task function +static void timer_task_func(void *task_data, void *worker_state); static void flush_logs(void) @@ -59,6 +70,7 @@ flush_logs(void) // Check if active buffer has any logs to flush if (sentry__atomic_fetch(&lq.buffers[current_active].count) == 0) { // Active buffer is empty, try the other buffer + // TODO do we want this? flush_buffer_idx = 1 - current_active; if (sentry__atomic_fetch(&lq.buffers[flush_buffer_idx].count) == 0) { // Both buffers are empty, nothing to flush @@ -74,7 +86,7 @@ flush_logs(void) log_buffer_t *flush_buffer = &lq.buffers[flush_buffer_idx]; long count = sentry__atomic_fetch(&flush_buffer->count); - if (count == 0) { + if (count == 0) { // TODO when can this happen? // Buffer became empty while we were setting up, nothing to do sentry__atomic_store(&lq.flushing, 0); return; @@ -114,7 +126,8 @@ static bool enqueu_log(sentry_value_t log) { // Retry loop in case buffer switches during our attempt - for (int retry = 0; retry < 10; retry++) { + // TODO do we want this? adds busy waiting of 1ms + for (int retry = 0; retry < 1; retry++) { // Get current active buffer index long buffer_idx = sentry__atomic_fetch(&lq.active_buffer); log_buffer_t *current_buffer = &lq.buffers[buffer_idx]; @@ -146,16 +159,51 @@ enqueu_log(sentry_value_t log) long was_running = sentry__atomic_fetch_and_add(&lq.timer_running, 1); if (was_running == 0) { - // We're the first to set the timer, spawn the thread - sentry_threadid_t timer_thread; - sentry__thread_init(&timer_thread); - if (sentry__thread_spawn( - &timer_thread, timer_thread_func, NULL) - != 0) { - SENTRY_WARN("Failed to spawn timer thread"); + // We're the first to set the timer, ensure bgworker exists + // and submit task + if (!g_logs_state.timer_worker) { + g_logs_state.timer_worker + = sentry__bgworker_new(NULL, NULL); + if (g_logs_state.timer_worker) { + sentry__bgworker_setname( + g_logs_state.timer_worker, "sentry-timer"); + if (sentry__bgworker_start( + g_logs_state.timer_worker) + != 0) { + SENTRY_WARN("Failed to start timer bgworker"); + sentry__bgworker_decref( + g_logs_state.timer_worker); + g_logs_state.timer_worker = NULL; + sentry__atomic_fetch_and_add( + &lq.timer_running, -1); + } + } else { + SENTRY_WARN("Failed to create timer bgworker"); + sentry__atomic_fetch_and_add(&lq.timer_running, -1); + } + } + + // Submit timer task if worker is available and no task is + // already submitted + if (g_logs_state.timer_worker + && !sentry__atomic_fetch( + &g_logs_state.timer_task_submitted)) { + sentry__atomic_store( + &g_logs_state.timer_task_submitted, 1); + if (sentry__bgworker_submit(g_logs_state.timer_worker, + timer_task_func, NULL, NULL) + != 0) { + SENTRY_WARN("Failed to submit timer task"); + sentry__atomic_fetch_and_add(&lq.timer_running, -1); + sentry__atomic_store( + &g_logs_state.timer_task_submitted, 0); + } + } else if (!g_logs_state.timer_worker) { + // No worker available, reset the running flag sentry__atomic_fetch_and_add(&lq.timer_running, -1); } else { - sentry__thread_detach(timer_thread); + // Task already submitted, reset the running flag + sentry__atomic_fetch_and_add(&lq.timer_running, -1); } } else { // Timer was already running, decrement back @@ -185,10 +233,11 @@ enqueu_log(sentry_value_t log) return false; } -SENTRY_THREAD_FN -timer_thread_func(void *arg) +static void +timer_task_func(void *task_data, void *worker_state) { - (void)arg; // unused parameter + (void)task_data; // unused parameter + (void)worker_state; // unused parameter // Sleep for 5 seconds #ifdef SENTRY_PLATFORM_WINDOWS @@ -200,10 +249,9 @@ timer_thread_func(void *arg) // Try to flush logs - this will flush whichever buffer has content flush_logs(); - // Reset timer state - decrement the counter + // Reset timer state - decrement the counter and mark task as completed sentry__atomic_fetch_and_add(&lq.timer_running, -1); - - return 0; + sentry__atomic_store(&g_logs_state.timer_task_submitted, 0); } static const char * @@ -601,3 +649,30 @@ sentry_log_fatal(const char *message, ...) sentry__logs_log(SENTRY_LEVEL_FATAL, message, args); va_end(args); } + +void +sentry__logs_shutdown(uint64_t timeout) +{ + SENTRY_DEBUG("shutting down logs system"); + + // Shutdown the timer bgworker if it exists + if (g_logs_state.timer_worker) { + if (sentry__bgworker_shutdown(g_logs_state.timer_worker, timeout) + != 0) { + SENTRY_WARN( + "timer bgworker did not shut down cleanly within timeout"); + } + // TODO this already happens inside worker_thread + // sentry__bgworker_decref(g_logs_state.timer_worker); + // g_logs_state.timer_worker = NULL; + } + + // Reset state flags + sentry__atomic_store(&g_logs_state.timer_task_submitted, 0); + sentry__atomic_store(&lq.timer_running, 0); + + // Perform final flush to ensure any remaining logs are sent + flush_logs(); + + SENTRY_DEBUG("logs system shutdown complete"); +} diff --git a/src/sentry_logs.h b/src/sentry_logs.h index 5fa6a4a77..fc5450cda 100644 --- a/src/sentry_logs.h +++ b/src/sentry_logs.h @@ -5,4 +5,11 @@ void sentry__logs_log(sentry_level_t level, const char *message, va_list args); +/** + * Instructs the logs bgworker to shut down. + * + * Returns 0 on success. + */ +void sentry__logs_shutdown(uint64_t timeout); + #endif From d07ef33bb1746da0d52af6c20f98b1f022798dd3 Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Mon, 11 Aug 2025 16:24:31 +0200 Subject: [PATCH 11/14] add first integration tests --- examples/example.c | 99 ++++++++++++++++++++++++++-------- src/sentry_envelope.c | 2 + tests/__init__.py | 1 + tests/assertions.py | 25 +++++++++ tests/test_integration_http.py | 64 ++++++++++++++++++++++ tests/unit/test_logs.c | 4 +- 6 files changed, 172 insertions(+), 23 deletions(-) diff --git a/examples/example.c b/examples/example.c index 0db09aa16..9c7425573 100644 --- a/examples/example.c +++ b/examples/example.c @@ -24,6 +24,7 @@ # define sleep_s(SECONDS) Sleep((SECONDS) * 1000) #else +# include # include # include @@ -272,6 +273,44 @@ 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 = 25; + for (int i = 0; i < LOG_COUNT; i++) { + sentry_log_debug( + "thread log %d on thread %lu", i, get_current_thread_id()); + } + return 0; +} +#elif defined(SENTRY_PLATFORM_MACOS) +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; +} +#else +void * +log_thread_func(void *arg) +{ + (void)arg; + int LOG_COUNT = 25; + 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) { @@ -395,28 +434,44 @@ 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, (uint64_t)18446744073709551615); - sentry_log_warn("This is a medium number as unsigned %" PRIu64, - (uint64_t)9007199254740991); - sentry_log_warn("This is a medium number as signed %" PRId64, - (int64_t)9007199254740991); - 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, "logs-timer")) { + for (int i = 0; i < 10; i++) { + sentry_log_info("Informational log nr.%d", i); + } +#ifdef SENTRY_PLATFORM_WINDOWS + Sleep(6000); + +#else + sleep_s(6); +#endif + sentry_log_debug("post-sleep log"); + } + if (has_arg(argc, argv, "logs-threads")) { + // we should see two envelopes make its way to Sentry + // Spawn multiple threads to test concurrent logging +#ifdef SENTRY_PLATFORM_WINDOWS + const int NUM_THREADS = 3; + HANDLE threads[NUM_THREADS]; + for (int t = 0; t < NUM_THREADS; t++) { + threads[t] + = CreateThread(NULL, 0, log_thread_func, NULL, 0, NULL); + } + Sleep(6000); + for (int t = 0; t < NUM_THREADS; t++) { + CloseHandle(threads[t]); + } +#else + const int NUM_THREADS = 50; + pthread_t threads[NUM_THREADS]; + for (int t = 0; t < NUM_THREADS; t++) { + pthread_create(&threads[t], NULL, log_thread_func, NULL); + } + sleep_s(6); + for (int t = 0; t < NUM_THREADS; t++) { + pthread_join(threads[t], NULL); + } +#endif + } } if (!has_arg(argc, argv, "no-setup")) { diff --git a/src/sentry_envelope.c b/src/sentry_envelope.c index 23852485c..e19272d4a 100644 --- a/src/sentry_envelope.c +++ b/src/sentry_envelope.c @@ -424,6 +424,8 @@ sentry__envelope_add_logs(sentry_envelope_t *envelope, sentry_value_t logs) 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/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..b104eb9d3 100644 --- a/tests/assertions.py +++ b/tests/assertions.py @@ -226,6 +226,31 @@ def assert_attachment(envelope): ) +def assert_logs(envelope, expected_item_count=1, expected_trace_id=None): + logs = None + for item in envelope: + # TODO item.payload has no json; needs to be extracted during envelope deserialization probably + assert item.headers.get("type") == "log" + 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 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 + # 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..f81c374bb 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,66 @@ 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_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") + + run( + tmp_path, + "sentry_example", + ["log", "enable-logs", "logs-threads"], + check=True, + env=dict(os.environ, SENTRY_DSN=make_dsn(httpserver)), + ) + + assert len(httpserver.log) == 50 + + for i in range(50): + req = httpserver.log[i][0] + body = req.get_data() + + envelope = Envelope.deserialize(body) + assert_logs(envelope, 100) diff --git a/tests/unit/test_logs.c b/tests/unit/test_logs.c index 2628516ce..84fd8d2cb 100644 --- a/tests/unit/test_logs.c +++ b/tests/unit/test_logs.c @@ -47,7 +47,9 @@ SENTRY_TEST(basic_logging_functionality) sentry_close(); - TEST_CHECK_INT_EQUAL(called_transport, 1); + // 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) From b2dbe18969b93ebedffc1a861a4da978fa32be42 Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Mon, 11 Aug 2025 17:13:24 +0200 Subject: [PATCH 12/14] update example.c with correct log thread amounts --- examples/example.c | 19 +++---------------- 1 file changed, 3 insertions(+), 16 deletions(-) diff --git a/examples/example.c b/examples/example.c index 9c7425573..865468dcd 100644 --- a/examples/example.c +++ b/examples/example.c @@ -278,31 +278,19 @@ DWORD WINAPI log_thread_func(LPVOID lpParam) { (void)lpParam; - int LOG_COUNT = 25; + 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; } -#elif defined(SENTRY_PLATFORM_MACOS) -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; -} #else void * log_thread_func(void *arg) { (void)arg; - int LOG_COUNT = 25; + 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()); @@ -449,8 +437,8 @@ main(int argc, char **argv) if (has_arg(argc, argv, "logs-threads")) { // we should see two envelopes make its way to Sentry // Spawn multiple threads to test concurrent logging + const int NUM_THREADS = 50; #ifdef SENTRY_PLATFORM_WINDOWS - const int NUM_THREADS = 3; HANDLE threads[NUM_THREADS]; for (int t = 0; t < NUM_THREADS; t++) { threads[t] @@ -461,7 +449,6 @@ main(int argc, char **argv) CloseHandle(threads[t]); } #else - const int NUM_THREADS = 50; pthread_t threads[NUM_THREADS]; for (int t = 0; t < NUM_THREADS; t++) { pthread_create(&threads[t], NULL, log_thread_func, NULL); From ccd88d2dd3c488a5e1e4603ff92e14159c47f6ac Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Tue, 12 Aug 2025 11:35:14 +0200 Subject: [PATCH 13/14] cleanup --- examples/example.c | 12 +++----- src/sentry_logs.c | 76 ++++++++++++++++++++++------------------------ 2 files changed, 40 insertions(+), 48 deletions(-) diff --git a/examples/example.c b/examples/example.c index 865468dcd..d3335f817 100644 --- a/examples/example.c +++ b/examples/example.c @@ -426,16 +426,12 @@ main(int argc, char **argv) for (int i = 0; i < 10; i++) { sentry_log_info("Informational log nr.%d", i); } -#ifdef SENTRY_PLATFORM_WINDOWS - Sleep(6000); - -#else + // sleep >5s to trigger logs timer sleep_s(6); -#endif + // we should see two envelopes make its way to Sentry sentry_log_debug("post-sleep log"); } if (has_arg(argc, argv, "logs-threads")) { - // we should see two envelopes make its way to Sentry // Spawn multiple threads to test concurrent logging const int NUM_THREADS = 50; #ifdef SENTRY_PLATFORM_WINDOWS @@ -444,7 +440,7 @@ main(int argc, char **argv) threads[t] = CreateThread(NULL, 0, log_thread_func, NULL, 0, NULL); } - Sleep(6000); + sleep_s(3000); for (int t = 0; t < NUM_THREADS; t++) { CloseHandle(threads[t]); } @@ -453,7 +449,7 @@ main(int argc, char **argv) for (int t = 0; t < NUM_THREADS; t++) { pthread_create(&threads[t], NULL, log_thread_func, NULL); } - sleep_s(6); + sleep_s(3); for (int t = 0; t < NUM_THREADS; t++) { pthread_join(threads[t], NULL); } diff --git a/src/sentry_logs.c b/src/sentry_logs.c index 79126f183..2cd21d78f 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -55,39 +55,24 @@ static void flush_logs(void) { // Use atomic compare-and-swap to ensure only one thread flushes at a time - long expected = 0; - // TODO platform-agnostic? - if (!__sync_bool_compare_and_swap(&lq.flushing, expected, 1)) { + // TODO is this platform-agnostic? + if (!__sync_bool_compare_and_swap(&lq.flushing, 0, 1)) { // Another thread is already flushing return; } // Determine which buffer to flush - long current_active = sentry__atomic_fetch(&lq.active_buffer); - long flush_buffer_idx - = current_active; // Start by trying to flush the active buffer + long current_active_buffer_idx = sentry__atomic_fetch(&lq.active_buffer); + // Active buffer has logs, switch to the other buffer for new writes + long new_active = 1 - current_active_buffer_idx; + sentry__atomic_store(&lq.active_buffer, new_active); - // Check if active buffer has any logs to flush - if (sentry__atomic_fetch(&lq.buffers[current_active].count) == 0) { - // Active buffer is empty, try the other buffer - // TODO do we want this? - flush_buffer_idx = 1 - current_active; - if (sentry__atomic_fetch(&lq.buffers[flush_buffer_idx].count) == 0) { - // Both buffers are empty, nothing to flush - sentry__atomic_store(&lq.flushing, 0); - return; - } - } else { - // Active buffer has logs, switch to the other buffer for new writes - long new_active = 1 - current_active; - sentry__atomic_store(&lq.active_buffer, new_active); - } - - log_buffer_t *flush_buffer = &lq.buffers[flush_buffer_idx]; + log_buffer_t *flush_buffer = &lq.buffers[current_active_buffer_idx]; long count = sentry__atomic_fetch(&flush_buffer->count); - if (count == 0) { // TODO when can this happen? - // Buffer became empty while we were setting up, nothing to do + // Check if active buffer has any logs to flush + if (count == 0) { + // no need to swap sentry__atomic_store(&lq.flushing, 0); return; } @@ -97,6 +82,9 @@ flush_logs(void) sentry_value_t logs_list = sentry_value_new_list(); for (long i = 0; i < count; i++) { + // TODO reason about using a `sentry_value_t` list instead, as we could + // then just + // set the logs["items"] to that value sentry_value_append(logs_list, flush_buffer->logs[i]); } @@ -112,10 +100,11 @@ flush_logs(void) } // Free the logs object since envelope doesn't take ownership + // TODO if we replace by `sentry_value_t`, we could still decref + + // sentry_value_new_list? sentry_value_decref(logs); - // Reset the flushed buffer - this is now safe since we switched active - // buffer + // Reset the flushed buffer sentry__atomic_store(&flush_buffer->count, 0); // Clear flushing flag @@ -126,15 +115,21 @@ static bool enqueu_log(sentry_value_t log) { // Retry loop in case buffer switches during our attempt - // TODO do we want this? adds busy waiting of 1ms - for (int retry = 0; retry < 1; retry++) { + // TODO do we want this? adds busy waiting of 1ms per retry + int RETRY_COUNT = 0; + for (int retry = 0; retry <= RETRY_COUNT; retry++) { // Get current active buffer index long buffer_idx = sentry__atomic_fetch(&lq.active_buffer); log_buffer_t *current_buffer = &lq.buffers[buffer_idx]; // Try to get a slot in the current buffer long log_idx = sentry__atomic_fetch_and_add(¤t_buffer->count, 1); + long buffer_is_flushing; + // TODO we also need to check that the queue isn't begin flushed right + // now? or that there are still an X amount of logs being added which + // would make the queue full? + // -> think the latter is implicit in atomically getting the count if (log_idx < QUEUE_LENGTH) { // Successfully got a slot, write the log current_buffer->logs[log_idx] = log; @@ -166,7 +161,7 @@ enqueu_log(sentry_value_t log) = sentry__bgworker_new(NULL, NULL); if (g_logs_state.timer_worker) { sentry__bgworker_setname( - g_logs_state.timer_worker, "sentry-timer"); + g_logs_state.timer_worker, "sentry-logs-timer"); if (sentry__bgworker_start( g_logs_state.timer_worker) != 0) { @@ -198,11 +193,9 @@ enqueu_log(sentry_value_t log) sentry__atomic_store( &g_logs_state.timer_task_submitted, 0); } - } else if (!g_logs_state.timer_worker) { - // No worker available, reset the running flag - sentry__atomic_fetch_and_add(&lq.timer_running, -1); } else { - // Task already submitted, reset the running flag + // Worker unavailable or task already submitted, + // reset the running flag sentry__atomic_fetch_and_add(&lq.timer_running, -1); } } else { @@ -212,11 +205,13 @@ enqueu_log(sentry_value_t log) } return true; - } else { - // Buffer is full, roll back our increment - sentry__atomic_fetch_and_add(¤t_buffer->count, -1); + } + // Buffer is full, roll back our increment + sentry__atomic_fetch_and_add(¤t_buffer->count, -1); - // Try to trigger a flush to switch buffers + // TODO the flush below only makes sense if we retry + // Try to trigger a flush to switch buffers + if (RETRY_COUNT) { flush_logs(); // Brief pause before retry to allow flush to complete @@ -229,7 +224,8 @@ enqueu_log(sentry_value_t log) } // All retries exhausted - both buffers are likely full - SENTRY_WARN("Unable to enqueue log - all buffers full"); + SENTRY_WARNF("Unable to enqueue log - all buffers full. Log body: %s", + sentry_value_as_string(sentry_value_get_by_key(log, "body"))); return false; } @@ -662,7 +658,7 @@ sentry__logs_shutdown(uint64_t timeout) SENTRY_WARN( "timer bgworker did not shut down cleanly within timeout"); } - // TODO this already happens inside worker_thread + // TODO this already happens inside worker_thread right? // sentry__bgworker_decref(g_logs_state.timer_worker); // g_logs_state.timer_worker = NULL; } From 845f5bc8617b4ed127ba4118e8dda631b1beb768 Mon Sep 17 00:00:00 2001 From: JoshuaMoelans <60878493+JoshuaMoelans@users.noreply.github.com> Date: Tue, 12 Aug 2025 13:30:10 +0200 Subject: [PATCH 14/14] add wait for 'adding' logs in flush logic --- src/sentry_logs.c | 40 +++++++++++++++++++++++++++++----------- 1 file changed, 29 insertions(+), 11 deletions(-) diff --git a/src/sentry_logs.c b/src/sentry_logs.c index 2cd21d78f..e82ec42ca 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -21,6 +21,7 @@ typedef struct { sentry_value_t logs[QUEUE_LENGTH]; volatile long count; // Number of logs in this buffer + volatile long adding; // Number of logs trying to get added to this buffer } log_buffer_t; struct logs_queue { @@ -38,10 +39,11 @@ static struct { sentry_bgworker_t *timer_worker; volatile long timer_task_submitted; // 1 if timer task is submitted, 0 otherwise -} g_logs_state = { .queue = { .buffers = { { .count = 0 }, { .count = 0 } }, - .active_buffer = 0, - .timer_running = 0, - .flushing = 0 }, +} g_logs_state = { .queue + = { .buffers = { { .count = 0, .adding = 0 }, { .count = 0, .adding = 0 } }, + .active_buffer = 0, + .timer_running = 0, + .flushing = 0 }, .timer_worker = NULL, .timer_task_submitted = 0 }; @@ -52,7 +54,7 @@ static struct { static void timer_task_func(void *task_data, void *worker_state); static void -flush_logs(void) +flush_logs(int from_length) { // Use atomic compare-and-swap to ensure only one thread flushes at a time // TODO is this platform-agnostic? @@ -68,6 +70,16 @@ flush_logs(void) sentry__atomic_store(&lq.active_buffer, new_active); log_buffer_t *flush_buffer = &lq.buffers[current_active_buffer_idx]; + while (sentry__atomic_fetch(&flush_buffer->adding) != from_length) { + SENTRY_DEBUG("waiting for add to be finished"); + // TODO is there a better way to do this than a busy wait? +#ifdef SENTRY_PLATFORM_WINDOWS + Sleep(1); +#else + usleep(20); // 1ms +#endif + } + // all adds have concluded long count = sentry__atomic_fetch(&flush_buffer->count); // Check if active buffer has any logs to flush @@ -121,22 +133,27 @@ enqueu_log(sentry_value_t log) // Get current active buffer index long buffer_idx = sentry__atomic_fetch(&lq.active_buffer); log_buffer_t *current_buffer = &lq.buffers[buffer_idx]; + // TODO we should add 1 to the 'adding' counter here, even if it fails + // to avoid flush mistiming with an in-flight log + sentry__atomic_fetch_and_add(¤t_buffer->adding, 1); // Try to get a slot in the current buffer long log_idx = sentry__atomic_fetch_and_add(¤t_buffer->count, 1); - long buffer_is_flushing; + // long buffer_is_flushing; // TODO we also need to check that the queue isn't begin flushed right // now? or that there are still an X amount of logs being added which // would make the queue full? // -> think the latter is implicit in atomically getting the count + // TODO the && !lq.flushing isn't necessary UNLESS both queues are + // flushing! if (log_idx < QUEUE_LENGTH && !lq.flushing) { if (log_idx < QUEUE_LENGTH) { // Successfully got a slot, write the log current_buffer->logs[log_idx] = log; // Check if this buffer is now full and trigger flush if (log_idx == QUEUE_LENGTH - 1) { - flush_logs(); + flush_logs(1); } // Start timer thread if this is the first log in any buffer @@ -203,7 +220,7 @@ enqueu_log(sentry_value_t log) sentry__atomic_fetch_and_add(&lq.timer_running, -1); } } - + sentry__atomic_fetch_and_add(¤t_buffer->adding, -1); return true; } // Buffer is full, roll back our increment @@ -212,7 +229,7 @@ enqueu_log(sentry_value_t log) // TODO the flush below only makes sense if we retry // Try to trigger a flush to switch buffers if (RETRY_COUNT) { - flush_logs(); + // flush_logs(); // Brief pause before retry to allow flush to complete #ifdef SENTRY_PLATFORM_WINDOWS @@ -221,6 +238,7 @@ enqueu_log(sentry_value_t log) usleep(1000); // 1ms #endif } + sentry__atomic_fetch_and_add(¤t_buffer->adding, -1); } // All retries exhausted - both buffers are likely full @@ -243,7 +261,7 @@ timer_task_func(void *task_data, void *worker_state) #endif // Try to flush logs - this will flush whichever buffer has content - flush_logs(); + flush_logs(0); // Reset timer state - decrement the counter and mark task as completed sentry__atomic_fetch_and_add(&lq.timer_running, -1); @@ -668,7 +686,7 @@ sentry__logs_shutdown(uint64_t timeout) sentry__atomic_store(&lq.timer_running, 0); // Perform final flush to ensure any remaining logs are sent - flush_logs(); + flush_logs(0); SENTRY_DEBUG("logs system shutdown complete"); }