diff --git a/examples/example.c b/examples/example.c index bb4f1cd5a..d3335f817 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,32 @@ create_debug_crumb(const char *message) return debug_crumb; } +#ifdef SENTRY_PLATFORM_WINDOWS +DWORD WINAPI +log_thread_func(LPVOID lpParam) +{ + (void)lpParam; + int LOG_COUNT = 100; + for (int i = 0; i < LOG_COUNT; i++) { + sentry_log_debug( + "thread log %d on thread %lu", i, get_current_thread_id()); + } + return 0; +} +#else +void * +log_thread_func(void *arg) +{ + (void)arg; + int LOG_COUNT = 100; + for (int i = 0; i < LOG_COUNT; i++) { + sentry_log_debug( + "thread log %d on thread %llu", i, get_current_thread_id()); + } + return NULL; +} +#endif + int main(int argc, char **argv) { @@ -381,6 +408,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, "attachment")) { @@ -389,6 +420,43 @@ main(int argc, char **argv) sentry_attachment_set_content_type(bytes, "application/octet-stream"); } + // TODO incorporate into test + if (sentry_options_get_enable_logs(options)) { + if (has_arg(argc, argv, "logs-timer")) { + for (int i = 0; i < 10; i++) { + sentry_log_info("Informational log nr.%d", i); + } + // sleep >5s to trigger logs timer + sleep_s(6); + // we should see two envelopes make its way to Sentry + sentry_log_debug("post-sleep log"); + } + if (has_arg(argc, argv, "logs-threads")) { + // Spawn multiple threads to test concurrent logging + const int NUM_THREADS = 50; +#ifdef SENTRY_PLATFORM_WINDOWS + HANDLE threads[NUM_THREADS]; + for (int t = 0; t < NUM_THREADS; t++) { + threads[t] + = CreateThread(NULL, 0, log_thread_func, NULL, 0, NULL); + } + sleep_s(3000); + for (int t = 0; t < NUM_THREADS; t++) { + CloseHandle(threads[t]); + } +#else + pthread_t threads[NUM_THREADS]; + for (int t = 0; t < NUM_THREADS; t++) { + pthread_create(&threads[t], NULL, log_thread_func, NULL); + } + sleep_s(3); + for (int t = 0; t < NUM_THREADS; t++) { + pthread_join(threads[t], NULL); + } +#endif + } + } + if (!has_arg(argc, argv, "no-setup")) { sentry_set_transaction("test-transaction"); sentry_set_level(SENTRY_LEVEL_WARNING); @@ -630,6 +698,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 9b58351a8..d642fd133 100644 --- a/include/sentry.h +++ b/include/sentry.h @@ -442,6 +442,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, @@ -1866,6 +1867,22 @@ 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); + +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 48e8b0e82..5b8ccabc5 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -17,6 +17,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 d2e14593e..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" @@ -161,6 +162,7 @@ sentry_init(sentry_options_t *options) sentry_close(); sentry_logger_t logger = { NULL, NULL, SENTRY_LEVEL_DEBUG }; + if (options->debug) { logger = options->logger; } @@ -323,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_envelope.c b/src/sentry_envelope.c index 3fc69c188..e19272d4a 100644 --- a/src/sentry_envelope.c +++ b/src/sentry_envelope.c @@ -401,6 +401,35 @@ 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( + 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; +} + sentry_envelope_item_t * sentry__envelope_add_user_report( sentry_envelope_t *envelope, sentry_value_t user_report) diff --git a/src/sentry_envelope.h b/src/sentry_envelope.h index a41985dce..c52871217 100644 --- a/src/sentry_envelope.h +++ b/src/sentry_envelope.h @@ -49,6 +49,12 @@ sentry_envelope_item_t *sentry__envelope_add_transaction( sentry_envelope_item_t *sentry__envelope_add_user_report( sentry_envelope_t *envelope, sentry_value_t user_report); +/** + * 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_logger.c b/src/sentry_logger.c index 5051dab73..bef6f91c8 100644 --- a/src/sentry_logger.c +++ b/src/sentry_logger.c @@ -71,6 +71,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: @@ -89,8 +91,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..e82ec42ca --- /dev/null +++ b/src/sentry_logs.c @@ -0,0 +1,692 @@ +#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 "sentry_sync.h" + +#include +#include +#include + +// TODO think about this +#ifdef SENTRY_UNITTEST +# define QUEUE_LENGTH 5 +#else +# define QUEUE_LENGTH 100 +#endif +#define FLUSH_TIMER 5 + +typedef struct { + sentry_value_t logs[QUEUE_LENGTH]; + 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 { + 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; + +// 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, .adding = 0 }, { .count = 0, .adding = 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 task function +static void timer_task_func(void *task_data, void *worker_state); + +static 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? + if (!__sync_bool_compare_and_swap(&lq.flushing, 0, 1)) { + // Another thread is already flushing + return; + } + + // Determine which buffer to flush + 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); + + 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 + if (count == 0) { + // no need to swap + 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 (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]); + } + + sentry_value_set_by_key(logs, "items", logs_list); + + // Send 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 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 + sentry__atomic_store(&flush_buffer->count, 0); + + // Clear flushing flag + sentry__atomic_store(&lq.flushing, 0); +} + +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 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]; + // 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; + + // 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(1); + } + + // 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, 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-logs-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 { + // Worker unavailable or task already submitted, + // reset the running flag + sentry__atomic_fetch_and_add(&lq.timer_running, -1); + } + } else { + // Timer was already running, decrement back + 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 + sentry__atomic_fetch_and_add(¤t_buffer->count, -1); + + // 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 +#ifdef SENTRY_PLATFORM_WINDOWS + Sleep(1); +#else + usleep(1000); // 1ms +#endif + } + sentry__atomic_fetch_and_add(¤t_buffer->adding, -1); + } + + // All retries exhausted - both buffers are likely 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; +} + +static void +timer_task_func(void *task_data, void *worker_state) +{ + (void)task_data; // unused parameter + (void)worker_state; // unused parameter + + // Sleep for 5 seconds +#ifdef SENTRY_PLATFORM_WINDOWS + Sleep(FLUSH_TIMER * 1000); +#else + sleep(FLUSH_TIMER); +#endif + + // Try to flush logs - this will flush whichever buffer has content + flush_logs(0); + + // Reset timer state - decrement the counter and mark task as completed + sentry__atomic_fetch_and_add(&lq.timer_running, -1); + sentry__atomic_store(&g_logs_state.timer_task_submitted, 0); +} + +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': { + 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( + param_obj, "type", sentry_value_new_string("integer")); + break; + } + case 'u': + case 'x': + case 'X': + case 'o': { + 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; + } + 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); + enqueu_log(log); + } +} + +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); +} + +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 right? + // 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(0); + + SENTRY_DEBUG("logs system shutdown complete"); +} diff --git a/src/sentry_logs.h b/src/sentry_logs.h new file mode 100644 index 000000000..fc5450cda --- /dev/null +++ b/src/sentry_logs.h @@ -0,0 +1,15 @@ +#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); + +/** + * Instructs the logs bgworker to shut down. + * + * Returns 0 on success. + */ +void sentry__logs_shutdown(uint64_t timeout); + +#endif diff --git a/src/sentry_options.c b/src/sentry_options.c index 23eaef2b4..76f3d2352 100644 --- a/src/sentry_options.c +++ b/src/sentry_options.c @@ -674,6 +674,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 5316b69e5..ad7d9b11e 100644 --- a/src/sentry_options.h +++ b/src/sentry_options.h @@ -57,6 +57,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 */ 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 5cfe25bad..2c4d526bc 100644 --- a/src/sentry_value.c +++ b/src/sentry_value.c @@ -110,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: @@ -315,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(); } @@ -331,7 +333,7 @@ sentry_value_new_double(double value) sentry_value_t sentry_value_new_int64(int64_t value) { - thing_t *thing = sentry_malloc(sizeof(thing_t)); + thing_t *thing = SENTRY_MAKE(thing_t); if (!thing) { return sentry_value_new_null(); } @@ -347,7 +349,7 @@ sentry_value_new_int64(int64_t value) sentry_value_t sentry_value_new_uint64(uint64_t value) { - thing_t *thing = sentry_malloc(sizeof(thing_t)); + thing_t *thing = SENTRY_MAKE(thing_t); if (!thing) { return sentry_value_new_null(); } 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/CMakeLists.txt b/tests/unit/CMakeLists.txt index 624655e70..fe14d533a 100644 --- a/tests/unit/CMakeLists.txt +++ b/tests/unit/CMakeLists.txt @@ -30,6 +30,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..84fd8d2cb --- /dev/null +++ b/tests/unit/test_logs.c @@ -0,0 +1,104 @@ +#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(); + + // 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) +{ + 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_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, 1); +} diff --git a/tests/unit/tests.inc b/tests/unit/tests.inc index 63c71eeb1..1e6e28fae 100644 --- a/tests/unit/tests.inc +++ b/tests/unit/tests.inc @@ -17,6 +17,7 @@ XX(basic_http_request_preparation_for_minidump) XX(basic_http_request_preparation_for_transaction) XX(basic_http_request_preparation_for_user_feedback) XX(basic_http_request_preparation_for_user_report) +XX(basic_logging_functionality) XX(basic_spans) XX(basic_tracing_context) XX(basic_transaction) @@ -70,6 +71,7 @@ XX(dsn_without_url_scheme_is_invalid) XX(empty_transport) XX(event_with_id) XX(exception_without_type_or_value_still_valid) +XX(formatted_log_messages) XX(fuzz_json) XX(init_failure) XX(internal_uuid_api) @@ -77,6 +79,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)