Skip to content

Commit 1f8e4c4

Browse files
feat: structured logging (#1271)
* add sentry logs option * add sentry logs option to example * 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 #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 * fixed log parameter conversion * update example to avoid warning-as-error * feat(logs): batching (#1338) * initial queue attempt * add timer * prototype double buffer approach * update logs unit tests for batching * replace timer with bgworker * add first integration tests * update example.c with correct log thread amounts * cleanup * add wait for 'adding' logs in flush logic * go back to single queue for performance testing * add time checks * add ToDos + cleanup sentry_value_t cloning * initial attempt * cond_wait for timer + 'adding' spinlock * add sleep for tests * add sleep for tests * force flush before attempting timer_worker shutdown * add proper cond_wait for 'adding' counter * revert to manual flush on shutdown instead of timer thread flush * add separate timer_stop atomic * cleanup + replace 'adding' cond_wait by pure spinlock * change bgworker for simpler thread implementation * cleanup * fix memleak * fixes * cleanup * cleanup * windows fixes * update shutdown order * fixes * explicit check to stop timer task * windows cleanup * loosen threaded test assertion for CI - too much variability in thread scheduling, so we can expect pretty much anything * add continue for unexpected logs flush trigger instead of attempting flush * Windows re-add condition variable trigger case * feat(logs): add `before_send_log` (#1355) * add `before_send_log` callback * add `before_send_log` callback tests * (temporary) add debug for calling sentry_options_free * remove early return * add late return * cleanup * fix ownership issues in single buffer batching (#1362) * let the producer thread sleep for 1ms between logs * fix two missing NULL checks in the json serializer * clean up logging and early exits in `enqueue_log_single()` * clean up ownerships in logs * eliminate clones (we expect that everything outlives the logs being sent except local construction) * use incref everywhere where we ref global state. this was the cause of the UAF, partially solved with the clones but a few were missing. no reason to clone if we do not want to disconnect for a particular object graph * clarify that add_attribute expects ownership * minimize scope_mut by moving os_context out * raise that log output in throughput tests add to variability (stdout logging should be turned off when running a limit) * log error in case we weren't able to start the log batching worker * fix clang-cl warning * ci: fix failing mingw build (#1361) * ci: fix failing mingw build * split `ASM_MASM_COMPILER` and `_FLAGS` * add `ASM_MASM_FLAGS` in `mingw` install step * specify the `CMAKE_ASM_MASM_COMPILER` as a `FILEPATH` * clean up CMAKE_DEFINES construction so it is easier to diff in the future * fix `LLVM_MINGW_INSTALL_PATH` to be referenced locally rather than $env (cherry picked from commit 519554f) * use UNREACHABLE macro to fix anal warnings * batching double buffered (#1365) * first attempt at double buffered * remove the sleep from the windows thread func * clean up thread waiting in the example * adapt the double buffer to use retries, fix remaining issues, clean up and write inline docs * return early in example on sentry_init error. * fix formatting via shorter name for thread gate atomic * improve inline docs of log_buffer_t members * fetch os_context from scope * move scope/options data retrieval into separate function + add expected keys to test * update logs API to return status code * cleanup * add log-event trace connection test * remove duplicate test * specify macOS SDKROOT --------- Co-authored-by: JoshuaMoelans <[email protected]> * add flush retry for missed flush requests * move flush retry into flush function * add docs --------- Co-authored-by: Mischan Toosarani-Hausberger <[email protected]> * update CHANGELOG.md * use `trace_id` from scoped spans for logs * fix copy-paste leftover + docs * add log_sleep for thread test + variable NUM_LOGS * no `usleep` on windows :( * fix seconds->milliseconds * cleanup * test(logs): add 32-bit vargs test (#1370) * add vargs conversion test * add ifdef for 32-bit systems * Update tests/unit/test_logs.c Co-authored-by: Mischan Toosarani-Hausberger <[email protected]> * add comment * fix comment --------- Co-authored-by: Mischan Toosarani-Hausberger <[email protected]> * Apply suggestions from code review Co-authored-by: Mischan Toosarani-Hausberger <[email protected]> * post-merge cleanup * pin ruamel version * let's unpin ruamel.yaml.clib to get 0.2.14 which seemingly fixes the missing header: https://sourceforge.net/p/ruamel-yaml-clib/tickets/47/#de77 * add empty payload check * log output of logger tests if we fail to find the pre-crash marker * fix: move `is_tsan` marker into the `has_crashpad` condition... ...so we can ignore in which module a `crashpad` test runs. * fix: update `has_crashpad` condition comment * really only move `is_tsan`, but keep the module level `pytestmark` * CHANGELOG.md update * CHANGELOG.md update * CHANGELOG.md update --------- Co-authored-by: Mischan Toosarani-Hausberger <[email protected]>
1 parent d56701c commit 1f8e4c4

26 files changed

+1640
-14
lines changed

CHANGELOG.md

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,11 @@
11
# Changelog
22

3+
## Unreleased
4+
5+
**Features**:
6+
7+
- Add support for structured logs. It is currently experimental, and one can enable it by setting `sentry_options_set_enable_logs`. When enabled, you can capture a log using `sentry_log_info()` (or another log level). Logs can be filtered by setting the `before_send_log` hook. ([#1271](https://github.com/getsentry/sentry-native/pull/1271/))
8+
39
## 0.11.0
410

511
**Breaking changes**:

examples/example.c

Lines changed: 128 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@
2424
# define sleep_s(SECONDS) Sleep((SECONDS) * 1000)
2525
#else
2626

27+
# include <pthread.h>
2728
# include <signal.h>
2829
# include <unistd.h>
2930

@@ -158,6 +159,33 @@ discarding_before_transaction_callback(sentry_value_t tx, void *user_data)
158159
return tx;
159160
}
160161

162+
static sentry_value_t
163+
before_send_log_callback(sentry_value_t log, void *user_data)
164+
{
165+
(void)user_data;
166+
sentry_value_t attribute = sentry_value_new_object();
167+
sentry_value_set_by_key(
168+
attribute, "value", sentry_value_new_string("little"));
169+
sentry_value_set_by_key(
170+
attribute, "type", sentry_value_new_string("string"));
171+
sentry_value_set_by_key(sentry_value_get_by_key(log, "attributes"),
172+
"coffeepot.size", attribute);
173+
return log;
174+
}
175+
176+
static sentry_value_t
177+
discarding_before_send_log_callback(sentry_value_t log, void *user_data)
178+
{
179+
(void)user_data;
180+
if (sentry_value_is_null(
181+
sentry_value_get_by_key(sentry_value_get_by_key(log, "attributes"),
182+
"sentry.message.template"))) {
183+
sentry_value_decref(log);
184+
return sentry_value_new_null();
185+
}
186+
return log;
187+
}
188+
161189
// Test logger that outputs in a format the integration tests can parse
162190
static void
163191
test_logger_callback(
@@ -291,6 +319,42 @@ create_debug_crumb(const char *message)
291319
return debug_crumb;
292320
}
293321

322+
#define NUM_THREADS 50
323+
#define NUM_LOGS 100 // how many log calls each thread makes
324+
#define LOG_SLEEP_MS 1 // time (in ms) between log calls
325+
326+
#if defined(SENTRY_PLATFORM_WINDOWS)
327+
# define sleep_ms(MILLISECONDS) Sleep(MILLISECONDS)
328+
#else
329+
# define sleep_ms(MILLISECONDS) usleep(MILLISECONDS * 1000)
330+
#endif
331+
332+
#ifdef SENTRY_PLATFORM_WINDOWS
333+
DWORD WINAPI
334+
log_thread_func(LPVOID lpParam)
335+
{
336+
(void)lpParam;
337+
for (int i = 0; i < NUM_LOGS; i++) {
338+
sentry_log_debug(
339+
"thread log %d on thread %lu", i, get_current_thread_id());
340+
sleep_ms(LOG_SLEEP_MS);
341+
}
342+
return 0;
343+
}
344+
#else
345+
void *
346+
log_thread_func(void *arg)
347+
{
348+
(void)arg;
349+
for (int i = 0; i < NUM_LOGS; i++) {
350+
sentry_log_debug(
351+
"thread log %d on thread %llu", i, get_current_thread_id());
352+
sleep_ms(LOG_SLEEP_MS);
353+
}
354+
return NULL;
355+
}
356+
#endif
357+
294358
int
295359
main(int argc, char **argv)
296360
{
@@ -364,6 +428,16 @@ main(int argc, char **argv)
364428
options, discarding_before_transaction_callback, NULL);
365429
}
366430

431+
if (has_arg(argc, argv, "before-send-log")) {
432+
sentry_options_set_before_send_log(
433+
options, before_send_log_callback, NULL);
434+
}
435+
436+
if (has_arg(argc, argv, "discarding-before-send-log")) {
437+
sentry_options_set_before_send_log(
438+
options, discarding_before_send_log_callback, NULL);
439+
}
440+
367441
if (has_arg(argc, argv, "traces-sampler")) {
368442
sentry_options_set_traces_sampler(
369443
options, traces_sampler_callback, NULL);
@@ -416,14 +490,59 @@ main(int argc, char **argv)
416490
sentry_options_set_logger_enabled_when_crashed(options, 1);
417491
}
418492

419-
sentry_init(options);
493+
if (has_arg(argc, argv, "enable-logs")) {
494+
sentry_options_set_enable_logs(options, true);
495+
}
496+
497+
if (0 != sentry_init(options)) {
498+
return EXIT_FAILURE;
499+
}
420500

421501
if (has_arg(argc, argv, "attachment")) {
422502
sentry_attachment_t *bytes
423503
= sentry_attach_bytes("\xc0\xff\xee", 3, "bytes.bin");
424504
sentry_attachment_set_content_type(bytes, "application/octet-stream");
425505
}
426506

507+
if (sentry_options_get_enable_logs(options)) {
508+
if (has_arg(argc, argv, "capture-log")) {
509+
sentry_log_debug("I'm a log message!");
510+
}
511+
if (has_arg(argc, argv, "logs-timer")) {
512+
for (int i = 0; i < 10; i++) {
513+
sentry_log_info("Informational log nr.%d", i);
514+
}
515+
// sleep >5s to trigger logs timer
516+
sleep_s(6);
517+
// we should see two envelopes make its way to Sentry
518+
sentry_log_debug("post-sleep log");
519+
}
520+
if (has_arg(argc, argv, "logs-threads")) {
521+
// Spawn multiple threads to test concurrent logging
522+
#ifdef SENTRY_PLATFORM_WINDOWS
523+
HANDLE threads[NUM_THREADS];
524+
for (int t = 0; t < NUM_THREADS; t++) {
525+
threads[t]
526+
= CreateThread(NULL, 0, log_thread_func, NULL, 0, NULL);
527+
}
528+
529+
WaitForMultipleObjects(NUM_THREADS, threads, TRUE, INFINITE);
530+
531+
for (int t = 0; t < NUM_THREADS; t++) {
532+
CloseHandle(threads[t]);
533+
}
534+
#else
535+
pthread_t threads[NUM_THREADS];
536+
for (int t = 0; t < NUM_THREADS; t++) {
537+
pthread_create(&threads[t], NULL, log_thread_func, NULL);
538+
}
539+
for (int t = 0; t < NUM_THREADS; t++) {
540+
pthread_join(threads[t], NULL);
541+
}
542+
#endif
543+
}
544+
}
545+
427546
if (!has_arg(argc, argv, "no-setup")) {
428547
sentry_set_transaction("test-transaction");
429548
sentry_set_level(SENTRY_LEVEL_WARNING);
@@ -670,9 +789,15 @@ main(int argc, char **argv)
670789
sentry_value_t event = sentry_value_new_message_event(
671790
SENTRY_LEVEL_INFO, "my-logger", "Hello World!");
672791
sentry_capture_event(event);
792+
if (has_arg(argc, argv, "logs-scoped-transaction")) {
793+
sentry_log_debug("logging during scoped transaction event");
794+
}
673795
}
674796

675797
sentry_transaction_finish(tx);
798+
if (has_arg(argc, argv, "logs-scoped-transaction")) {
799+
sentry_log_debug("logging after scoped transaction event");
800+
}
676801
}
677802

678803
if (has_arg(argc, argv, "capture-minidump")) {
@@ -689,4 +814,6 @@ main(int argc, char **argv)
689814
if (has_arg(argc, argv, "crash-after-shutdown")) {
690815
trigger_crash();
691816
}
817+
818+
return EXIT_SUCCESS;
692819
}

include/sentry.h

Lines changed: 78 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -442,6 +442,7 @@ SENTRY_API char *sentry_value_to_json(sentry_value_t value);
442442
* Sentry levels for events and breadcrumbs.
443443
*/
444444
typedef enum sentry_level_e {
445+
SENTRY_LEVEL_TRACE = -2,
445446
SENTRY_LEVEL_DEBUG = -1,
446447
SENTRY_LEVEL_INFO = 0,
447448
SENTRY_LEVEL_WARNING = 1,
@@ -1889,6 +1890,83 @@ SENTRY_EXPERIMENTAL_API void sentry_options_set_traces_sampler(
18891890
sentry_options_t *opts, sentry_traces_sampler_function callback,
18901891
void *user_data);
18911892

1893+
/**
1894+
* Enables or disables the structured logging feature.
1895+
* When disabled, all calls to sentry_logger_X() are no-ops.
1896+
*/
1897+
SENTRY_EXPERIMENTAL_API void sentry_options_set_enable_logs(
1898+
sentry_options_t *opts, int enable_logs);
1899+
SENTRY_EXPERIMENTAL_API int sentry_options_get_enable_logs(
1900+
const sentry_options_t *opts);
1901+
1902+
/**
1903+
* The potential returns of calling any of the sentry_log_X functions
1904+
* - Success means a log was enqueued
1905+
* - Discard means the `before_send_log` function discarded the log
1906+
* - Failed means the log wasn't enqueued. This happens if the buffers are full
1907+
* - Disabled means the option `enable_logs` was false.
1908+
*/
1909+
typedef enum {
1910+
SENTRY_LOG_RETURN_SUCCESS = 0,
1911+
SENTRY_LOG_RETURN_DISCARD = 1,
1912+
SENTRY_LOG_RETURN_FAILED = 2,
1913+
SENTRY_LOG_RETURN_DISABLED = 3
1914+
} log_return_value_t;
1915+
1916+
/**
1917+
* Structured logging interface. Minimally blocks the client trying to log,
1918+
* but is therefore lossy when enqueueing a log fails
1919+
* (e.g. when both buffers are full).
1920+
*
1921+
* Format string restrictions:
1922+
* Only a subset of printf format specifiers are supported for parameter
1923+
* extraction. Supported specifiers include:
1924+
* - %d, %i - signed integers (treated as long long)
1925+
* - %u, %x, %X, %o - unsigned integers (treated as unsigned long long)
1926+
* - %f, %F, %e, %E, %g, %G - floating point numbers (treated as double)
1927+
* - %c - single character
1928+
* - %s - null-terminated string (null pointers are handled as "(null)")
1929+
* - %p - pointer value (formatted as hexadecimal string)
1930+
*
1931+
* Unsupported format specifiers will consume their corresponding argument
1932+
* but will be recorded as "(unknown)" in the structured log data.
1933+
* Length modifiers (h, l, L, z, j, t) are parsed but ignored.
1934+
*
1935+
* Because of this, please only use 64-bit types/casts for your arguments.
1936+
*
1937+
* Flags, width, and precision specifiers are parsed but currently ignored for
1938+
* parameter extraction purposes.
1939+
*/
1940+
SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_trace(
1941+
const char *message, ...);
1942+
SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_debug(
1943+
const char *message, ...);
1944+
SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_info(
1945+
const char *message, ...);
1946+
SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_warn(
1947+
const char *message, ...);
1948+
SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_error(
1949+
const char *message, ...);
1950+
SENTRY_EXPERIMENTAL_API log_return_value_t sentry_log_fatal(
1951+
const char *message, ...);
1952+
1953+
/**
1954+
* Type of the `before_send_log` callback.
1955+
*
1956+
* The callback takes ownership of the `log`, and should usually return
1957+
* that same log. In case the log should be discarded, the
1958+
* callback needs to call `sentry_value_decref` on the provided log, and
1959+
* return a `sentry_value_new_null()` instead.
1960+
*/
1961+
typedef sentry_value_t (*sentry_before_send_log_function_t)(
1962+
sentry_value_t log, void *user_data);
1963+
1964+
/**
1965+
* Sets the `before_send_log` callback.
1966+
*/
1967+
SENTRY_EXPERIMENTAL_API void sentry_options_set_before_send_log(
1968+
sentry_options_t *opts, sentry_before_send_log_function_t func, void *data);
1969+
18921970
#ifdef SENTRY_PLATFORM_LINUX
18931971

18941972
/**

src/CMakeLists.txt

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,8 @@ sentry_target_sources_cwd(sentry
1717
sentry_json.h
1818
sentry_logger.c
1919
sentry_logger.h
20+
sentry_logs.c
21+
sentry_logs.h
2022
sentry_options.c
2123
sentry_options.h
2224
sentry_os.c

src/sentry_core.c

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@
88
#include "sentry_core.h"
99
#include "sentry_database.h"
1010
#include "sentry_envelope.h"
11+
#include "sentry_logs.h"
1112
#include "sentry_options.h"
1213
#include "sentry_path.h"
1314
#include "sentry_random.h"
@@ -165,6 +166,7 @@ sentry_init(sentry_options_t *options)
165166
sentry_close();
166167

167168
sentry_logger_t logger = { NULL, NULL, SENTRY_LEVEL_DEBUG };
169+
168170
if (options->debug) {
169171
logger = options->logger;
170172
}
@@ -287,6 +289,10 @@ sentry_init(sentry_options_t *options)
287289
sentry_start_session();
288290
}
289291

292+
if (options->enable_logs) {
293+
sentry__logs_startup();
294+
}
295+
290296
sentry__mutex_unlock(&g_options_lock);
291297
return 0;
292298

@@ -313,6 +319,15 @@ sentry_flush(uint64_t timeout)
313319
int
314320
sentry_close(void)
315321
{
322+
// Shutdown logs system before locking options to ensure logs are flushed.
323+
// This prevents a potential deadlock on the options during log envelope
324+
// creation.
325+
SENTRY_WITH_OPTIONS (options) {
326+
if (options->enable_logs) {
327+
sentry__logs_shutdown(options->shutdown_timeout);
328+
}
329+
}
330+
316331
SENTRY__MUTEX_INIT_DYN_ONCE(g_options_lock);
317332
// this function is to be called only once, so we do not allow more than one
318333
// caller

0 commit comments

Comments
 (0)