From 30127b492f290caeb3c86b39755d8f757fd7b916 Mon Sep 17 00:00:00 2001 From: Giovanni M Guidini Date: Thu, 20 Aug 2026 13:56:42 +0200 Subject: [PATCH 1/7] Offline buffer: grow to 16 slots, shared with no priority tier MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Raised both examples' NVS-backed offline buffer from 8 to 16 slots, and documented in the README how to size that number: sentry_storage_nvs() already accepts any count up to SENTRY_NVS_MAX_SLOTS (64), so a smaller firmware can and should pass a smaller one — 16 is just these examples' own choice against the stock 20 KB partition, not a ceiling the SDK imposes. One shared ring across every envelope type, oldest evicted first, with no priority between categories and no separate buffer per category. Deliberately not solving this with reserved slots for crash reports: logs are opt-in, more connected context on one event can be worth more than a duplicate event with less, and the real fix for reliable delivery is a transport that keeps delivering, not triage over whose envelope keeps its slot. Also added an NTP time sync in wifi_basic after WiFi comes up and before the first send attempt, since the example never set the clock otherwise and an ESP32 has no battery-backed RTC. 133 host tests pass; both examples build clean for esp32dev. --- README.md | 13 ++++++++++++- examples/wifi_basic/src/main.cpp | 18 +++++++++++++----- .../usermods/sentry/usermod_sentry.cpp | 4 ++-- 3 files changed, 27 insertions(+), 8 deletions(-) diff --git a/README.md b/README.md index 179e15f..2f55940 100644 --- a/README.md +++ b/README.md @@ -387,7 +387,7 @@ matters more here than on a desktop: the most valuable event this SDK produces of the crash that just happened — is built at boot, *before* the radio has associated. ```cpp -sentry_enable_buffering(sentry_storage_nvs(8)); // or storage_fs(), below +sentry_enable_buffering(sentry_storage_nvs(16)); // or storage_fs(), below ... void loop() { if (sentry_buffered_count() > 0) sentry_flush(2); // on an interval, not every pass @@ -407,6 +407,17 @@ space, and the filesystem backend never calls `begin()` — a reporter that refo partition of user data to report a crash would be worse than the crash. Everything is confined to a `sentry` namespace / `/sentry` directory. +**Sizing `slots`** is a flash budget question, not a correctness one: `sentry_storage_nvs()` +accepts any count from 1 up to `SENTRY_NVS_MAX_SLOTS` (64) and rejects anything outside that +range rather than clamping it. An envelope runs roughly 1 KB, so slots × 1 KB is what you are +spending against whatever partition you gave the buffer — the stock 20 KB `nvs` partition +makes 16 a comfortable ceiling before NVS has no room left for anything else you keep there. +Weigh that against how long the device is realistically offline at a stretch: more slots +survive a longer outage, at the cost of the flash they occupy whether or not they are ever +used. This is one ring shared by every envelope type with no priority between them, so a +size chosen too small is what an unrelated high-volume category — Application Metrics +today, see below — can evict a crash report from. + Writing your own is five functions (`write`, `read`, `erase`, `load_meta`, `save_meta`) — the same vtable pattern as transports, which is what lets the ring logic be host-tested against a plain array. diff --git a/examples/wifi_basic/src/main.cpp b/examples/wifi_basic/src/main.cpp index 6d45801..a20f6ed 100644 --- a/examples/wifi_basic/src/main.cpp +++ b/examples/wifi_basic/src/main.cpp @@ -479,12 +479,20 @@ void setup() } /* - * Buffering, before anything is sent. Eight slots of NVS is roughly 6 KB of the stock - * 20 KB partition. Anything that cannot be delivered now is persisted and retried by - * sentry_flush() below, which is what makes a boot-time crash report survive having no - * network at the moment it is created. + * Buffering, before anything is sent. Sixteen slots of NVS is roughly 12-16 KB of the + * stock 20 KB partition (envelopes here run ~1 KB each) — this example's own choice for + * its own partition, not a ceiling the SDK imposes; sentry_storage_nvs() accepts any + * count up to SENTRY_NVS_MAX_SLOTS and a smaller firmware should pass a smaller one. + * Anything that cannot be delivered now is persisted and retried by sentry_flush() + * below, which is what makes a boot-time crash report survive having no network at the + * moment it is created. + * + * One shared ring across every envelope type, oldest evicted first, with no priority + * between them — a high-volume category left unattended for long enough can still + * evict something that mattered more. The fix for that is a transport that keeps + * delivering, not triage over whose envelope gets to keep its slot. */ - if (!sentry_enable_buffering(sentry_storage_nvs(8))) { + if (!sentry_enable_buffering(sentry_storage_nvs(16))) { Serial.println("[sentry] NVS unavailable — running without an offline buffer"); } Serial.printf("[sentry] %u envelope(s) buffered from a previous run, %u dropped\n", diff --git a/examples/wled_http_forwarder/usermods/sentry/usermod_sentry.cpp b/examples/wled_http_forwarder/usermods/sentry/usermod_sentry.cpp index dd7b354..6e7dad1 100644 --- a/examples/wled_http_forwarder/usermods/sentry/usermod_sentry.cpp +++ b/examples/wled_http_forwarder/usermods/sentry/usermod_sentry.cpp @@ -108,10 +108,10 @@ class UsermodSentry : public Usermod { DEBUG_PRINTLN(F("[sentry] init failed — check SENTRY_DSN")); } - /* Eight slots of NVS, same as wifi_basic. Anything the forwarder can't take right + /* Sixteen slots of NVS, same as wifi_basic. Anything the forwarder can't take right * now survives here and is retried by loop()'s sentry_flush() below — including * across a reboot, which is the case this whole design exists for. */ - if (!sentry_enable_buffering(sentry_storage_nvs(8))) { + if (!sentry_enable_buffering(sentry_storage_nvs(16))) { DEBUG_PRINTLN(F("[sentry] NVS unavailable — running without an offline buffer")); } From 88cc51d0c84c6cdca2055511e26697533e2fcee3 Mon Sep 17 00:00:00 2001 From: Giovanni M Guidini Date: Thu, 20 Aug 2026 14:42:32 +0200 Subject: [PATCH 2/7] Logs: a continuous console, correlated by trace and device MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit sentry_log(level, fmt, ...) records one console line into a fixed 8x81 ring (src/core/sentry_log.c/.h), mirroring Application Metrics: recording never sends, so it is safe to call from a hot path a transaction cannot afford to trace. Unlike a metric, each line keeps its own trace_id, captured when it was recorded rather than resolved once for the whole batch — a line written during a real operation stays attached to it even if the operation has ended by the time the ring flushes. An idle-recorded line gets a fallback trace_id minted locally for that one envelope, never written to the device's active trace. Every line also carries device_id as an attribute, the correlation axis that is always available regardless of trace state. flush_logs() is called from sentry_flush() only, same as flush_metrics() — not from every trace transition as first built. That would have turned sentry_trace_adopt()/start()/release(), which wrap every request, into occasional blocking network calls; per-entry trace_id capture already makes correctness independent of when the ring happens to flush, so the extra call sites bought nothing but the regression. sentry_logs_dropped_count() is backed by a persistent g_state.logs_dropped counter, incremented from sentry_log_ring_push()'s new bool return (true on eviction), the same split metrics uses between its own reset-per-flush table counter and its lifetime g_state.metrics_dropped — the ring's internal `dropped` field alone would have reset on every successful flush. 15 new host tests (17 after the audit below), plus test_filter wiring in platformio.ini. Verified against the real firmware, not just the host suite: pio test -e native never compiles sentry_micro.c at all (build_src_filter = +), so the flush wiring was only checked by building all four default chip variants directly. Reviewed with review-work + test-audit before this commit: - Fixed the dropped-count and blocking-hot-path issues above. - Corrected a stale test comment (wrong eviction count in a comment). - Added a doc note against putting secrets in a log body. - Added tests for the previously-unasserted eviction return value, the timestamp derivation's two underflow clamps, and the envelope writer's size-probing/truncation-safety contract. - Filed, but did not fix here, a pre-existing flush_metrics()/ sentry_trace_start() bug that now also affects log trace attribution (SDK-1418) — logs sidestep it by not reusing sentry_trace_start() for their own fallback, but the root cause is unmodified, already-shipped code out of scope for this change. --- platformio.ini | 1 + src/core/sentry_log.c | 194 +++++++++++++++++++++ src/core/sentry_log.h | 107 ++++++++++++ src/sentry_micro.c | 92 +++++++++- src/sentry_micro.h | 37 ++++ test/test_log/test_log.c | 362 +++++++++++++++++++++++++++++++++++++++ 6 files changed, 790 insertions(+), 3 deletions(-) create mode 100644 src/core/sentry_log.c create mode 100644 src/core/sentry_log.h create mode 100644 test/test_log/test_log.c diff --git a/platformio.ini b/platformio.ini index b697764..d5b5410 100644 --- a/platformio.ini +++ b/platformio.ini @@ -27,6 +27,7 @@ test_filter = test_trace test_span test_metrics + test_log ; Compile the portable core into the test binary. `src/device` and `src/transport` are ; excluded: they are chip-specific by definition and are covered by the per-variant diff --git a/src/core/sentry_log.c b/src/core/sentry_log.c new file mode 100644 index 0000000..2ee2acf --- /dev/null +++ b/src/core/sentry_log.c @@ -0,0 +1,194 @@ +#include "sentry_log.h" + +#include +#include + +#include "sentry_json.h" + +void sentry_log_ring_reset(sentry_log_ring_t *ring) +{ + if (ring) { + memset(ring, 0, sizeof(*ring)); + } +} + +bool sentry_log_ring_push(sentry_log_ring_t *ring, sentry_level_t level, const char *trace_id, + uint64_t uptime_us, const char *body) +{ + if (!ring || !body) { + return false; + } + + uint8_t index; + bool evicted = false; + if (ring->count == SENTRY_MICRO_MAX_LOGS) { + /* Full: evict the oldest to make room. Unlike the metrics table, there is no + * running total to protect here — the newest line is worth more than the one it + * replaces, for a continuous stream. */ + index = ring->head; + ring->head = (uint8_t)((ring->head + 1) % SENTRY_MICRO_MAX_LOGS); + if (ring->dropped < UINT16_MAX) { + ring->dropped++; + } + evicted = true; + } else { + index = (uint8_t)((ring->head + ring->count) % SENTRY_MICRO_MAX_LOGS); + ring->count++; + } + + sentry_log_entry_t *entry = &ring->entries[index]; + snprintf(entry->body, sizeof(entry->body), "%s", body); + snprintf(entry->trace_id, sizeof(entry->trace_id), "%s", trace_id ? trace_id : ""); + entry->uptime_us = uptime_us; + entry->level = level; + entry->used = true; + return evicted; +} + +bool sentry_log_ring_empty(const sentry_log_ring_t *ring) { return !ring || ring->count == 0; } + +/** Sentry's log severity levels, mapping 1:1 onto sentry_level_t — only WARNING differs. */ +static const char *log_level_name(sentry_level_t level) +{ + switch (level) { + 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 "info"; + } +} + +/** Lowest number in each level's range — see develop.sentry.dev/sdk/telemetry/logs. */ +static int log_severity_number(sentry_level_t level) +{ + switch (level) { + case SENTRY_LEVEL_DEBUG: + return 5; + case SENTRY_LEVEL_INFO: + return 9; + case SENTRY_LEVEL_WARNING: + return 13; + case SENTRY_LEVEL_ERROR: + return 17; + case SENTRY_LEVEL_FATAL: + return 21; + default: + return 9; + } +} + +/** + * This entry's wall-clock timestamp, derived from the flush-time anchor. + * + * Both clocks are read at the same instant (the flush moment), so subtracting how long ago + * this entry's uptime was from that instant's uptime gives how long ago it happened — the + * same derivation sentry_transaction_start_unix_us() does for a span's start, applied per + * entry here instead of once. Clamped rather than left to underflow if the entry is somehow + * newer than the anchor (should not happen; entries are always recorded before the flush + * that serialises them), the same defensiveness that function already has. + */ +static uint64_t entry_unix_us( + const sentry_log_entry_t *entry, uint64_t now_uptime_us, uint64_t now_unix_us) +{ + uint64_t elapsed = now_uptime_us > entry->uptime_us ? now_uptime_us - entry->uptime_us : 0; + return elapsed > now_unix_us ? now_unix_us : now_unix_us - elapsed; +} + +static uint8_t write_items(sentry_json_t *writer, const sentry_log_ring_t *ring, + const char *fallback_trace_id, const char *device_id, uint64_t now_uptime_us, + uint64_t now_unix_us) +{ + uint8_t count = 0; + sentry_json_key(writer, "items"); + sentry_json_array_begin(writer); + for (uint8_t i = 0; i < ring->count; i++) { + const sentry_log_entry_t *entry = &ring->entries[(ring->head + i) % SENTRY_MICRO_MAX_LOGS]; + if (!entry->used) { + continue; + } + sentry_json_object_begin(writer); + sentry_json_kv_micros( + writer, "timestamp", entry_unix_us(entry, now_uptime_us, now_unix_us)); + /* Recorded trace wins; an idle-recorded line falls back to the one minted for this + * batch, the same rule flush_metrics() already applies. */ + sentry_json_kv_string( + writer, "trace_id", entry->trace_id[0] ? entry->trace_id : fallback_trace_id); + sentry_json_kv_string(writer, "level", log_level_name(entry->level)); + sentry_json_kv_string(writer, "body", entry->body); + sentry_json_key(writer, "severity_number"); + sentry_json_int(writer, log_severity_number(entry->level)); + if (device_id && device_id[0]) { + sentry_json_key(writer, "attributes"); + sentry_json_object_begin(writer); + sentry_json_key(writer, "device_id"); + sentry_json_object_begin(writer); + sentry_json_kv_string(writer, "value", device_id); + sentry_json_kv_string(writer, "type", "string"); + sentry_json_object_end(writer); + sentry_json_object_end(writer); + } + sentry_json_object_end(writer); + count++; + } + sentry_json_array_end(writer); + return count; +} + +size_t sentry_log_envelope_write(char *buf, size_t cap, const sentry_log_ring_t *ring, + const char *fallback_trace_id, const char *device_id, uint64_t now_uptime_us, + uint64_t now_unix_us) +{ + if (buf && cap > 0) { + buf[0] = '\0'; + } + if (!ring || !fallback_trace_id || !fallback_trace_id[0] || now_unix_us == 0 + || sentry_log_ring_empty(ring)) { + return 0; + } + + /* Count first, same reason as the metrics and event writers: the item header states + * the payload length before the payload itself is known. */ + sentry_json_t counter; + sentry_json_init(&counter, NULL, 0); + sentry_json_object_begin(&counter); + uint8_t item_count + = write_items(&counter, ring, fallback_trace_id, device_id, now_uptime_us, now_unix_us); + sentry_json_object_end(&counter); + size_t payload_len = counter.len; + + char header[128]; + int header_len = snprintf(header, sizeof(header), + "{}\n{\"type\":\"log\",\"item_count\":%u," + "\"content_type\":\"application/vnd.sentry.items.log+json\",\"length\":%u}\n", + (unsigned)item_count, (unsigned)payload_len); + if (header_len < 0 || (size_t)header_len >= sizeof(header)) { + return 0; + } + + size_t total = (size_t)header_len + payload_len + 1; + if (!buf) { + return total; + } + if (total + 1 > cap) { + buf[0] = '\0'; + return total; + } + + memcpy(buf, header, (size_t)header_len); + sentry_json_t writer; + sentry_json_init(&writer, buf + header_len, cap - (size_t)header_len); + sentry_json_object_begin(&writer); + write_items(&writer, ring, fallback_trace_id, device_id, now_uptime_us, now_unix_us); + sentry_json_object_end(&writer); + buf[header_len + payload_len] = '\n'; + buf[total] = '\0'; + return total; +} diff --git a/src/core/sentry_log.h b/src/core/sentry_log.h new file mode 100644 index 0000000..2f73c6a --- /dev/null +++ b/src/core/sentry_log.h @@ -0,0 +1,107 @@ +/** + * Logs — a continuous console, not a story about one event. + * + * Every entry carries its own trace_id, captured when it is recorded rather than resolved + * once for the whole batch the way a metric is: a line written during a real operation + * belongs to that operation's trace, the same way a breadcrumb would. A line recorded while + * idle carries an empty trace_id at record time; sentry_log_envelope_write() fills in a + * fallback for those, the same "mint one for the batch" answer flush_metrics() already uses, + * since an idle log line is not a causal claim the way a real trace attachment is. + * + * Fixed ring, no allocation, oldest evicted first: unlike the metrics table, there is no + * running total here to protect by refusing new entries — for a continuous stream, the + * newest line is worth more than the old one it replaces. + */ +#ifndef SENTRY_MICRO_LOG_H_INCLUDED +#define SENTRY_MICRO_LOG_H_INCLUDED + +#include "sentry_boot.h" +#include "sentry_envelope.h" /* sentry_level_t */ +#include "sentry_trace.h" /* SENTRY_MICRO_TRACE_ID_LEN */ + +#ifdef __cplusplus +extern "C" { +#endif + +/** + * Entries held at once. Matches SENTRY_MICRO_MAX_METRICS: how many of a small accumulating + * thing this SDK holds between flushes has one answer, not a new one per feature. + */ +#ifndef SENTRY_MICRO_MAX_LOGS +# define SENTRY_MICRO_MAX_LOGS 8 +#endif + +/** + * Bytes a single entry's body holds, including the terminator. Matches a conventional + * terminal line width. A longer message is truncated to fit, not dropped — a shortened line + * the operator can still read beats losing it entirely. + */ +#ifndef SENTRY_MICRO_LOG_BODY_LEN +# define SENTRY_MICRO_LOG_BODY_LEN 81 +#endif + +typedef struct { + char body[SENTRY_MICRO_LOG_BODY_LEN]; + /** Empty when recorded with no trace active; resolved to a fallback at write time. */ + char trace_id[SENTRY_MICRO_TRACE_ID_LEN]; + uint64_t uptime_us; + sentry_level_t level; + bool used; +} sentry_log_entry_t; + +typedef struct { + sentry_log_entry_t entries[SENTRY_MICRO_MAX_LOGS]; + /** Index of the oldest entry. */ + uint8_t head; + uint8_t count; + /** Entries evicted to make room before they were ever sent. Reported, never silent. */ + uint16_t dropped; +} sentry_log_ring_t; + +/** Empty the ring. */ +void sentry_log_ring_reset(sentry_log_ring_t *ring); + +/** + * Record one line, evicting the oldest entry first if the ring is already full. + * + * `trace_id` is copied verbatim — pass an empty string when nothing is active, resolved to + * a fallback only when the ring is serialised. `body` is truncated to + * SENTRY_MICRO_LOG_BODY_LEN - 1 characters if longer; formatting the message is the caller's + * job, same split as everywhere else in this SDK that takes a finished string. + * + * Returns true when an existing entry was evicted to make room for this one. The new line + * is always recorded either way — nothing about this call ever rejects it — so the return + * value exists only so a caller can count what was lost, the same role + * sentry_metrics_count()/gauge()'s bool return plays for a name that did not fit. + */ +bool sentry_log_ring_push(sentry_log_ring_t *ring, sentry_level_t level, const char *trace_id, + uint64_t uptime_us, const char *body); + +/** True when there is nothing worth sending, which is the common case between flushes. */ +bool sentry_log_ring_empty(const sentry_log_ring_t *ring); + +/** + * Write a complete envelope carrying every entry in the ring, oldest first. + * + * `fallback_trace_id` fills in any entry that had no trace active when it was recorded. + * `device_id` is attached to every entry as an attribute — the correlation axis that is + * always available, independent of whichever trace_id an idle-recorded entry ends up with. + * + * `now_uptime_us` and `now_unix_us` are both read at the same instant (the flush moment) and + * anchor each entry's stored monotonic uptime to a wall-clock timestamp — the same + * derivation sentry_transaction_start_unix_us() does for a span's start, done per entry here + * instead of once. + * + * Returns 0 when the ring is empty or `now_unix_us` is 0: a device that has not been told + * the date holds its logs rather than sending them anchored to the epoch, the same as + * metrics — a longer covered interval is still true, unlike a mistimed line. + */ +size_t sentry_log_envelope_write(char *buf, size_t cap, const sentry_log_ring_t *ring, + const char *fallback_trace_id, const char *device_id, uint64_t now_uptime_us, + uint64_t now_unix_us); + +#ifdef __cplusplus +} +#endif + +#endif /* SENTRY_MICRO_LOG_H_INCLUDED */ diff --git a/src/sentry_micro.c b/src/sentry_micro.c index afd844d..4079b91 100644 --- a/src/sentry_micro.c +++ b/src/sentry_micro.c @@ -47,6 +47,17 @@ typedef struct { sentry_metrics_t metrics; uint32_t metrics_dropped; + /** Console lines accumulated between flushes. See core/sentry_log.h. */ + sentry_log_ring_t log_ring; + /** + * Lines evicted from the ring since sentry_init(), persistent across flushes. + * + * Separate from log_ring.dropped on purpose, same split as metrics/metrics_dropped: + * the ring's own counter describes the batch about to be sent and is cleared with it, + * so a lifetime counter has to live outside anything a flush resets. + */ + uint32_t logs_dropped; + /** * The trace the *previous* boot died inside, recovered from RTC memory. * @@ -360,6 +371,80 @@ void sentry_metric_gauge(const char *name, int64_t value, const char *unit) uint32_t sentry_metrics_dropped_count(void) { return g_state.metrics_dropped; } +void sentry_log(sentry_level_t level, const char *message, ...) +{ + if (!g_state.enabled || !message) { + return; + } + char body[SENTRY_MICRO_LOG_BODY_LEN]; + va_list args; + va_start(args, message); + vsnprintf(body, sizeof(body), message, args); + va_end(args); + + /* Recorded verbatim, or empty if nothing is active — resolved to a fallback only at + * flush time. This is what lets a line written during a real operation stay attached to + * it even if the operation has ended by the time the ring is serialised. */ + if (sentry_log_ring_push(&g_state.log_ring, level, + g_state.trace.active ? g_state.trace.trace_id : "", sentry_device_uptime_us(), body)) { + g_state.logs_dropped++; + } +} + +uint32_t sentry_logs_dropped_count(void) { return g_state.logs_dropped; } + +/** + * Send whatever has accumulated in the log ring, if anything has. + * + * Called from sentry_flush() only — never from sentry_log() itself, for the same reason + * flush_metrics() (below) is never called from the recording calls: recording touches a + * ring, and only a flush touches the transport. + * + * Unlike flush_metrics(), this never mints a trace by calling sentry_trace_start(): doing + * so mutates g_state.trace and never releases it again, which is harmless the way metrics + * uses it but would be wrong here — the fallback below is scoped to this one envelope only. + */ +static void flush_logs(void) +{ + if (sentry_log_ring_empty(&g_state.log_ring)) { + return; + } + + /* Every log needs a timestamp, so a device that has not been told the date cannot send + * yet. Held rather than dropped, same reasoning as metrics: a longer covered interval is + * still true, unlike a line timestamped to the epoch. */ + uint64_t now_unix_us = sentry_device_unix_time_us(); + if (now_unix_us == 0) { + debug_log("holding logs: the device has not been told the date"); + return; + } + + /* A fallback trace_id for any entry that had none active when it was recorded — minted + * locally for this flush only and never written to g_state.trace, so it cannot outlive + * the envelope it was minted for. */ + char fallback_trace_id[SENTRY_MICRO_TRACE_ID_LEN] = { 0 }; + uint8_t trace_bytes[16]; + if (sentry_device_random(trace_bytes, sizeof(trace_bytes))) { + sentry_trace_id_format(fallback_trace_id, trace_bytes); + } + + char envelope[SENTRY_MICRO_ENVELOPE_BUFFER_BYTES]; + size_t needed = sentry_log_envelope_write(envelope, sizeof(envelope), &g_state.log_ring, + fallback_trace_id, g_state.device.device_id, sentry_device_uptime_us(), now_unix_us); + if (needed == 0 || needed >= sizeof(envelope)) { + debug_log("logs need %u bytes, envelope buffer is %u", (unsigned)needed, + (unsigned)sizeof(envelope)); + return; + } + + sentry_response_t response = sentry_send_envelope((const uint8_t *)envelope, needed); + /* Cleared whether or not the send succeeded, same reasoning as flush_metrics(): a failed + * send has already been buffered for retry by sentry_send_envelope() if it was worth + * retrying, so keeping the ring too would resend every line on the next flush. */ + sentry_log_ring_reset(&g_state.log_ring); + debug_log("flushed logs: result %d", (int)response.result); +} + /** * Send whatever has accumulated, if anything has. * @@ -572,10 +657,11 @@ uint32_t sentry_flush(uint32_t max_events) if (!g_state.enabled || in_backoff()) { return 0; } - /* Before the buffered envelopes, and outside the buffering check: metrics accumulate - * whether or not offline buffering was ever enabled, and a device that never buffers - * still wants its heap reported. */ + /* Before the buffered envelopes, and outside the buffering check: metrics and logs + * accumulate whether or not offline buffering was ever enabled, and a device that never + * buffers still wants its heap reported and its console mirrored. */ flush_metrics(); + flush_logs(); if (!g_state.buffering) { return 0; diff --git a/src/sentry_micro.h b/src/sentry_micro.h index 25a96fd..bc2ce4c 100644 --- a/src/sentry_micro.h +++ b/src/sentry_micro.h @@ -36,6 +36,7 @@ #include "core/sentry_buffer.h" #include "core/sentry_dsn.h" #include "core/sentry_envelope.h" +#include "core/sentry_log.h" #include "core/sentry_metrics.h" #include "core/sentry_span.h" #include "core/sentry_throttle.h" @@ -433,6 +434,42 @@ void sentry_metric_gauge(const char *name, int64_t value, const char *unit); */ uint32_t sentry_metrics_dropped_count(void); +/** + * Record one console line — a mirror of the serial output for a device with no cable + * attached. + * + * sentry_log(SENTRY_LEVEL_WARNING, "WiFi reconnect attempt %u", attempt); + * + * **This does not send.** Same shape as `sentry_metric_count()`/`sentry_metric_gauge()`: it + * writes into a fixed ring and returns, and the ring rides the next `sentry_flush()` — the + * property that makes it safe to call from a hot path a transaction cannot afford to trace. + * + * Unlike a metric, each line remembers whatever trace was active when it was recorded: a + * line written during a real operation is attached to that operation, the same way a + * breadcrumb would be, rather than to whatever is active (or nothing) by the time the ring + * happens to flush. A line recorded while idle is still held and still sent — logging the + * console is the point even when nothing else is going on — just without that attachment. + * + * `message` is formatted (printf-style) into a fixed buffer and truncated to fit; formatting + * a message that is about to be truncated is cheaper than growing the ring to avoid it. + * + * The ring holds `SENTRY_MICRO_MAX_LOGS` lines and evicts the oldest once full — unlike the + * metrics table, there is no running total to protect here, so the newest line displacing + * the oldest is the right trade for a continuous stream. + * + * `message` is sent to Sentry like any other log line — do not put a DSN, WiFi password, or + * anything else secret into it, the same rule as any logging call. + */ +void sentry_log(sentry_level_t level, const char *message, ...); + +/** + * Lines dropped because the ring was full, since `sentry_init()`. + * + * Moves whenever logging outpaces `sentry_flush()`'s cadence — the ring is short by design, + * so a chatty stretch between flushes is expected to cost old lines, not a bug. + */ +uint32_t sentry_logs_dropped_count(void); + /** * Report a message — the ordinary, non-crash way to tell Sentry something happened. * diff --git a/test/test_log/test_log.c b/test/test_log/test_log.c new file mode 100644 index 0000000..47816ff --- /dev/null +++ b/test/test_log/test_log.c @@ -0,0 +1,362 @@ +/** + * Host tests for the log ring. + * + * Two properties matter here that do not for metrics: entries are not aggregated — each one + * is distinct and keeps its own trace_id, recorded rather than resolved once at flush — and + * the ring evicts the oldest entry when full rather than refusing the newest, because there + * is no running total here worth protecting. + */ + +#include +#include +#include + +#include "sentry_log.h" + +#define TRACE "d49d9bf66f13450b81f65bc51cf49c03" +#define FALLBACK_TRACE "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" +#define DEVICE_ID "d4e9f486ed14" +/* 2026-08-19T00:00:00Z in microseconds. */ +#define NOW_UNIX_US 1755561600000000ULL + +void setUp(void) { } +void tearDown(void) { } + +static void test_a_line_is_recorded(void) +{ + sentry_log_ring_t r; + sentry_log_ring_reset(&r); + + TEST_ASSERT_TRUE(sentry_log_ring_empty(&r)); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "boot complete"); + TEST_ASSERT_FALSE(sentry_log_ring_empty(&r)); + TEST_ASSERT_EQUAL_UINT(1, r.count); + TEST_ASSERT_EQUAL_STRING("boot complete", r.entries[0].body); + TEST_ASSERT_EQUAL_STRING(TRACE, r.entries[0].trace_id); +} + +static void test_lines_are_not_aggregated(void) +{ + sentry_log_ring_t r; + sentry_log_ring_reset(&r); + + /* Unlike a metric, two identical bodies are two entries, not one accumulated total. */ + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "tick"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 2000, "tick"); + TEST_ASSERT_EQUAL_UINT(2, r.count); +} + +static void test_a_full_ring_evicts_the_oldest_not_the_newest(void) +{ + sentry_log_ring_t r; + char body[16]; + sentry_log_ring_reset(&r); + + for (int i = 0; i < SENTRY_MICRO_MAX_LOGS; i++) { + snprintf(body, sizeof(body), "line-%d", i); + TEST_ASSERT_FALSE( + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, (uint64_t)i * 1000, body)); + } + TEST_ASSERT_EQUAL_UINT(SENTRY_MICRO_MAX_LOGS, r.count); + TEST_ASSERT_EQUAL_UINT(0, r.dropped); + + /* One more evicts line-0, not line-7: the newest line is worth more than the one it + * replaces, unlike a metrics table protecting a running total. The return value is the + * production signal sentry_log()/logs_dropped_count() actually depend on — not just the + * ring's own internal counter, which happens to move for the same reason but is a + * separate field. */ + TEST_ASSERT_TRUE(sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 99000, "one-too-many")); + TEST_ASSERT_EQUAL_UINT(SENTRY_MICRO_MAX_LOGS, r.count); + TEST_ASSERT_EQUAL_UINT(1, r.dropped); + + char buf[2048]; + size_t len = sentry_log_envelope_write( + buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 100000, NOW_UNIX_US); + TEST_ASSERT_TRUE(len > 0 && len < sizeof(buf)); + TEST_ASSERT_NULL(strstr(buf, "\"line-0\"")); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"one-too-many\"")); +} + +static void test_entries_serialise_oldest_first(void) +{ + sentry_log_ring_t r; + char body[16]; + sentry_log_ring_reset(&r); + + for (int i = 0; i < SENTRY_MICRO_MAX_LOGS; i++) { + snprintf(body, sizeof(body), "line-%d", i); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, (uint64_t)i * 1000, body); + } + /* One more evicts line-0, so the ring now holds line-1..line-8 in that order. */ + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 8000, "line-8"); + + char buf[2048]; + size_t len = sentry_log_envelope_write( + buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 9000, NOW_UNIX_US); + TEST_ASSERT_TRUE(len > 0 && len < sizeof(buf)); + + const char *p2 = strstr(buf, "\"line-2\""); + const char *p8 = strstr(buf, "\"line-8\""); + TEST_ASSERT_NOT_NULL(p2); + TEST_ASSERT_NOT_NULL(p8); + TEST_ASSERT_TRUE(p2 < p8); +} + +static void test_an_overlong_body_is_truncated_not_dropped(void) +{ + sentry_log_ring_t r; + char long_body[200]; + sentry_log_ring_reset(&r); + + memset(long_body, 'x', sizeof(long_body) - 1); + long_body[sizeof(long_body) - 1] = '\0'; + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, long_body); + + TEST_ASSERT_EQUAL_UINT(1, r.count); + /* Truncated to fit, not rejected: a shortened line the operator can still read beats + * losing it entirely. */ + TEST_ASSERT_EQUAL_UINT(SENTRY_MICRO_LOG_BODY_LEN - 1, strlen(r.entries[0].body)); +} + +static void test_recorded_trace_id_wins_over_the_fallback(void) +{ + sentry_log_ring_t r; + sentry_log_ring_reset(&r); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "during a real operation"); + + char buf[2048]; + size_t len = sentry_log_envelope_write( + buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 2000, NOW_UNIX_US); + TEST_ASSERT_TRUE(len > 0); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"trace_id\":\"" TRACE "\"")); + TEST_ASSERT_NULL(strstr(buf, "\"trace_id\":\"" FALLBACK_TRACE "\"")); +} + +static void test_an_idle_recorded_line_falls_back_to_the_batch_trace(void) +{ + sentry_log_ring_t r; + sentry_log_ring_reset(&r); + /* Empty trace_id: nothing was active when this line was recorded. */ + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, "", 1000, "while idle"); + + char buf[2048]; + size_t len = sentry_log_envelope_write( + buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 2000, NOW_UNIX_US); + TEST_ASSERT_TRUE(len > 0); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"trace_id\":\"" FALLBACK_TRACE "\"")); +} + +static void test_a_batch_may_mix_entries_from_different_traces(void) +{ + sentry_log_ring_t r; + sentry_log_ring_reset(&r); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "during the operation"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, "", 2000, "after it ended"); + + char buf[2048]; + size_t len = sentry_log_envelope_write( + buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 3000, NOW_UNIX_US); + TEST_ASSERT_TRUE(len > 0); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"trace_id\":\"" TRACE "\"")); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"trace_id\":\"" FALLBACK_TRACE "\"")); +} + +static void test_writes_a_log_envelope(void) +{ + sentry_log_ring_t r; + char buf[2048]; + sentry_log_ring_reset(&r); + + sentry_log_ring_push(&r, SENTRY_LEVEL_WARNING, TRACE, 1000, "reconnect attempt 3"); + + size_t len = sentry_log_envelope_write( + buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 501000, NOW_UNIX_US); + TEST_ASSERT_TRUE(len > 0 && len < sizeof(buf)); + + TEST_ASSERT_NOT_NULL(strstr(buf, "\"type\":\"log\"")); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"item_count\":1")); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"content_type\":\"application/vnd.sentry.items.log+json\"")); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"body\":\"reconnect attempt 3\"")); + /* SENTRY_LEVEL_WARNING is the one level that does not map onto its own name. */ + TEST_ASSERT_NOT_NULL(strstr(buf, "\"level\":\"warn\"")); + TEST_ASSERT_NULL(strstr(buf, "\"level\":\"warning\"")); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"severity_number\":13")); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"trace_id\":\"" TRACE "\"")); + TEST_ASSERT_NOT_NULL(strstr( + buf, "\"attributes\":{\"device_id\":{\"value\":\"" DEVICE_ID "\",\"type\":\"string\"}}")); + + /* Entry recorded 500ms of uptime before the flush anchor: its timestamp is the flush's + * wall-clock anchor minus that same 500ms, not the flush time itself. */ + TEST_ASSERT_NOT_NULL(strstr(buf, "\"timestamp\":1755561599.500000")); +} + +static void test_entry_unix_us_clamps_instead_of_underflowing(void) +{ + sentry_log_ring_t r; + char buf[2048]; + + /* An entry that looks newer than the flush anchor should not happen, but if it did, + * elapsed clamps to 0 rather than underflowing — the entry reads as "now", not as a + * huge wrapped uint64. */ + sentry_log_ring_reset(&r); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 5000, "x"); + TEST_ASSERT_TRUE(sentry_log_envelope_write( + buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 1000, NOW_UNIX_US) + > 0); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"timestamp\":1755561600.000000")); + + /* An elapsed uptime longer than the wall clock itself (unreachable in practice — no + * device has decades of continuous uptime — but the arithmetic must not wrap) clamps to + * the flush's own anchor instead of underflowing past it. */ + sentry_log_ring_reset(&r); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 0, "x"); + TEST_ASSERT_TRUE(sentry_log_envelope_write(buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, + NOW_UNIX_US + 1000000, NOW_UNIX_US) + > 0); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"timestamp\":1755561600.000000")); +} + +static void test_envelope_write_reports_the_size_it_needs(void) +{ + sentry_log_ring_t r; + sentry_log_ring_reset(&r); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "boot complete"); + + /* Dry run, then a real one that must agree. */ + size_t needed + = sentry_log_envelope_write(NULL, 0, &r, FALLBACK_TRACE, DEVICE_ID, 2000, NOW_UNIX_US); + TEST_ASSERT_TRUE(needed > 0); + + char buf[2048]; + TEST_ASSERT_EQUAL_size_t(needed, + sentry_log_envelope_write( + buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 2000, NOW_UNIX_US)); + + /* Too small: report the requirement, and emit nothing that could be mistaken for a + * complete envelope. */ + char small[16]; + TEST_ASSERT_EQUAL_size_t(needed, + sentry_log_envelope_write( + small, sizeof(small), &r, FALLBACK_TRACE, DEVICE_ID, 2000, NOW_UNIX_US)); + TEST_ASSERT_EQUAL_STRING("", small); +} + +static void test_every_level_maps_to_its_log_name_and_severity(void) +{ + static const struct { + sentry_level_t level; + const char *name; + int severity; + } cases[] = { + { SENTRY_LEVEL_DEBUG, "debug", 5 }, + { SENTRY_LEVEL_INFO, "info", 9 }, + { SENTRY_LEVEL_WARNING, "warn", 13 }, + { SENTRY_LEVEL_ERROR, "error", 17 }, + { SENTRY_LEVEL_FATAL, "fatal", 21 }, + }; + + for (size_t i = 0; i < sizeof(cases) / sizeof(cases[0]); i++) { + sentry_log_ring_t r; + char buf[2048]; + char expect_level[32]; + char expect_severity[32]; + sentry_log_ring_reset(&r); + sentry_log_ring_push(&r, cases[i].level, TRACE, 1000, "x"); + + size_t len = sentry_log_envelope_write( + buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 1000, NOW_UNIX_US); + TEST_ASSERT_TRUE(len > 0); + + snprintf(expect_level, sizeof(expect_level), "\"level\":\"%s\"", cases[i].name); + snprintf( + expect_severity, sizeof(expect_severity), "\"severity_number\":%d", cases[i].severity); + TEST_ASSERT_NOT_NULL(strstr(buf, expect_level)); + TEST_ASSERT_NOT_NULL(strstr(buf, expect_severity)); + } +} + +static void test_an_empty_ring_writes_nothing(void) +{ + sentry_log_ring_t r; + char buf[2048]; + sentry_log_ring_reset(&r); + + TEST_ASSERT_EQUAL_UINT(0, + sentry_log_envelope_write(buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 0, NOW_UNIX_US)); + TEST_ASSERT_EQUAL_STRING("", buf); +} + +static void test_no_clock_means_no_envelope(void) +{ + sentry_log_ring_t r; + char buf[2048]; + sentry_log_ring_reset(&r); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "x"); + + /* Held, not dropped: the caller keeps the ring and tries again once the device has been + * told the date, the same reasoning as metrics. */ + TEST_ASSERT_EQUAL_UINT( + 0, sentry_log_envelope_write(buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 2000, 0)); + TEST_ASSERT_EQUAL_STRING("", buf); +} + +static void test_no_fallback_trace_means_no_envelope(void) +{ + sentry_log_ring_t r; + char buf[2048]; + sentry_log_ring_reset(&r); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "x"); + + TEST_ASSERT_EQUAL_UINT( + 0, sentry_log_envelope_write(buf, sizeof(buf), &r, "", DEVICE_ID, 2000, NOW_UNIX_US)); + TEST_ASSERT_EQUAL_UINT( + 0, sentry_log_envelope_write(buf, sizeof(buf), &r, NULL, DEVICE_ID, 2000, NOW_UNIX_US)); +} + +static void test_a_missing_device_id_omits_attributes_not_the_envelope(void) +{ + sentry_log_ring_t r; + char buf[2048]; + sentry_log_ring_reset(&r); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "x"); + + size_t len + = sentry_log_envelope_write(buf, sizeof(buf), &r, FALLBACK_TRACE, NULL, 2000, NOW_UNIX_US); + TEST_ASSERT_TRUE(len > 0); + TEST_ASSERT_NULL(strstr(buf, "\"attributes\"")); +} + +static void test_null_is_safe(void) +{ + TEST_ASSERT_TRUE(sentry_log_ring_empty(NULL)); + sentry_log_ring_reset(NULL); + TEST_ASSERT_FALSE(sentry_log_ring_push(NULL, SENTRY_LEVEL_INFO, TRACE, 1000, "x")); + + sentry_log_ring_t r; + sentry_log_ring_reset(&r); + TEST_ASSERT_FALSE(sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, NULL)); + TEST_ASSERT_TRUE(sentry_log_ring_empty(&r)); +} + +int main(void) +{ + UNITY_BEGIN(); + RUN_TEST(test_a_line_is_recorded); + RUN_TEST(test_lines_are_not_aggregated); + RUN_TEST(test_a_full_ring_evicts_the_oldest_not_the_newest); + RUN_TEST(test_entries_serialise_oldest_first); + RUN_TEST(test_an_overlong_body_is_truncated_not_dropped); + RUN_TEST(test_recorded_trace_id_wins_over_the_fallback); + RUN_TEST(test_an_idle_recorded_line_falls_back_to_the_batch_trace); + RUN_TEST(test_a_batch_may_mix_entries_from_different_traces); + RUN_TEST(test_writes_a_log_envelope); + RUN_TEST(test_entry_unix_us_clamps_instead_of_underflowing); + RUN_TEST(test_envelope_write_reports_the_size_it_needs); + RUN_TEST(test_every_level_maps_to_its_log_name_and_severity); + RUN_TEST(test_an_empty_ring_writes_nothing); + RUN_TEST(test_no_clock_means_no_envelope); + RUN_TEST(test_no_fallback_trace_means_no_envelope); + RUN_TEST(test_a_missing_device_id_omits_attributes_not_the_envelope); + RUN_TEST(test_null_is_safe); + return UNITY_END(); +} From e8c750bfed99d49f38a1cec51d3a24501ba3fa63 Mon Sep 17 00:00:00 2001 From: Giovanni M Guidini Date: Thu, 20 Aug 2026 16:07:11 +0200 Subject: [PATCH 3/7] Logs: report truncation exactly, and fix a real capacity bug it exposed sentry_log() now captures vsnprintf()'s return value (previously discarded) to know exactly when a line was cut short, rather than predicting it. A compile-time per-argument size-checking C++ wrapper was designed and deliberately rejected in favor of this: it's exact instead of a conservative worst-case bound, it works for runtime format strings too, and it avoids introducing this codebase's first real template metaprogramming for a failure mode (a shortened log line) that vsnprintf already makes memory-safe on its own. Each entry now carries its own `truncated` bool, ORed with the ring's own defensive truncation of an oversized body (so a caller that bypasses sentry_log()'s vsnprintf and calls the ring API directly still gets a correct answer). Surfaced two ways: sentry_logs_truncated_count(), mirroring sentry_logs_dropped_count(), and a per-line attribute so Explore -> Logs shows which specific line was shortened. Wiring that attribute in surfaced a real, pre-existing capacity bug: a full ring of realistic-length log lines already didn't fit in SENTRY_MICRO_ENVELOPE_BUFFER_BYTES before this attribute ever existed (2290 bytes needed against a 2048 budget, for 8 entries at max body length). flush_logs() silently refuses to send over budget and never resets the ring, so a device in that state would get stuck indefinitely. Nothing caught it because every prior test used short bodies, never a full ring at realistic length. Fixed with three changes together, since renaming alone measured short: - SENTRY_MICRO_MAX_LOGS: 8 -> 6. - Attribute keys abbreviated (truncated -> t7d, device_id -> d_id). - Both attributes conditional -- t7d only when true, d_id only when given, and `attributes` itself omitted rather than written empty when neither applies. Worst case (6 entries, max-length bodies, all truncated, device_id present) now measures 1944 bytes against the 2048 budget. Added test_a_full_ring_of_worst_case_entries_fits_the_envelope_budget as a regression test for exactly this scenario. Also adds a plain (non-templated) sentry::log(...) C++ forwarding wrapper in sentry_micro.hpp. 153 host tests pass (20 in test_log.c); all four default chip variants build clean. --- src/core/sentry_log.c | 38 +++++++-- src/core/sentry_log.h | 22 +++++- src/sentry_micro.c | 23 +++++- src/sentry_micro.h | 12 ++- src/sentry_micro.hpp | 19 +++++ test/test_log/test_log.c | 167 ++++++++++++++++++++++++++++++--------- 6 files changed, 228 insertions(+), 53 deletions(-) diff --git a/src/core/sentry_log.c b/src/core/sentry_log.c index 2ee2acf..67c5ff1 100644 --- a/src/core/sentry_log.c +++ b/src/core/sentry_log.c @@ -13,7 +13,7 @@ void sentry_log_ring_reset(sentry_log_ring_t *ring) } bool sentry_log_ring_push(sentry_log_ring_t *ring, sentry_level_t level, const char *trace_id, - uint64_t uptime_us, const char *body) + uint64_t uptime_us, const char *body, bool truncated) { if (!ring || !body) { return false; @@ -41,6 +41,11 @@ bool sentry_log_ring_push(sentry_log_ring_t *ring, sentry_level_t level, const c snprintf(entry->trace_id, sizeof(entry->trace_id), "%s", trace_id ? trace_id : ""); entry->uptime_us = uptime_us; entry->level = level; + /* ORs the caller's own knowledge with this call's own copy: a caller that already sized + * `body` to fit (sentry_log()'s vsnprintf) contributes the true signal here, while one + * that did not (calling this directly with an oversized string) is still caught by the + * copy above having truncated it regardless of what `truncated` claimed. */ + entry->truncated = truncated || strlen(body) >= sizeof(entry->body); entry->used = true; return evicted; } @@ -125,14 +130,33 @@ static uint8_t write_items(sentry_json_t *writer, const sentry_log_ring_t *ring, sentry_json_kv_string(writer, "body", entry->body); sentry_json_key(writer, "severity_number"); sentry_json_int(writer, log_severity_number(entry->level)); - if (device_id && device_id[0]) { + + /* + * Attribute keys are abbreviated (`t7d`, `d_id`) rather than spelled out — an + * envelope's worth of these is billed against SENTRY_MICRO_ENVELOPE_BUFFER_BYTES + * per entry, and a full ring of maximum-length bodies is already close to that + * budget before attributes are added at all. Both are present only when they have + * something to say: `t7d` only when true, `d_id` only when a device_id was given, + * and `attributes` itself is skipped rather than written empty when neither applies. + */ + bool has_device_id = device_id && device_id[0]; + if (entry->truncated || has_device_id) { sentry_json_key(writer, "attributes"); sentry_json_object_begin(writer); - sentry_json_key(writer, "device_id"); - sentry_json_object_begin(writer); - sentry_json_kv_string(writer, "value", device_id); - sentry_json_kv_string(writer, "type", "string"); - sentry_json_object_end(writer); + if (entry->truncated) { + sentry_json_key(writer, "t7d"); + sentry_json_object_begin(writer); + sentry_json_kv_bool(writer, "value", entry->truncated); + sentry_json_kv_string(writer, "type", "boolean"); + sentry_json_object_end(writer); + } + if (has_device_id) { + sentry_json_key(writer, "d_id"); + sentry_json_object_begin(writer); + sentry_json_kv_string(writer, "value", device_id); + sentry_json_kv_string(writer, "type", "string"); + sentry_json_object_end(writer); + } sentry_json_object_end(writer); } sentry_json_object_end(writer); diff --git a/src/core/sentry_log.h b/src/core/sentry_log.h index 2f73c6a..9a4c2e2 100644 --- a/src/core/sentry_log.h +++ b/src/core/sentry_log.h @@ -24,11 +24,17 @@ extern "C" { #endif /** - * Entries held at once. Matches SENTRY_MICRO_MAX_METRICS: how many of a small accumulating - * thing this SDK holds between flushes has one answer, not a new one per feature. + * Entries held at once. + * + * Lower than SENTRY_MICRO_MAX_METRICS (8): a log entry's JSON is heavier per item than a + * metric's — a full body plus its own attributes, against a metric's bare name and number + * — so the same slot count does not fit the same envelope budget. Eight entries at maximum + * body length, each carrying its worst-case attributes, need more than + * SENTRY_MICRO_ENVELOPE_BUFFER_BYTES; six is what stays under it even in that worst case, + * not a number chosen for its own sake. */ #ifndef SENTRY_MICRO_MAX_LOGS -# define SENTRY_MICRO_MAX_LOGS 8 +# define SENTRY_MICRO_MAX_LOGS 6 #endif /** @@ -46,6 +52,8 @@ typedef struct { char trace_id[SENTRY_MICRO_TRACE_ID_LEN]; uint64_t uptime_us; sentry_level_t level; + /** Whether `body` is shorter than what was actually meant to be logged. */ + bool truncated; bool used; } sentry_log_entry_t; @@ -69,13 +77,19 @@ void sentry_log_ring_reset(sentry_log_ring_t *ring); * SENTRY_MICRO_LOG_BODY_LEN - 1 characters if longer; formatting the message is the caller's * job, same split as everywhere else in this SDK that takes a finished string. * + * `truncated` is the caller's own knowledge that `body` is shorter than what was meant to be + * logged — typically vsnprintf()'s return value compared against the buffer it formatted + * into, information this call cannot recover once `body` already reflects the loss. This + * call ORs that with its own truncation of `body` into the ring's fixed field, so a caller + * that has not already sized `body` to fit still gets a correct answer. + * * Returns true when an existing entry was evicted to make room for this one. The new line * is always recorded either way — nothing about this call ever rejects it — so the return * value exists only so a caller can count what was lost, the same role * sentry_metrics_count()/gauge()'s bool return plays for a name that did not fit. */ bool sentry_log_ring_push(sentry_log_ring_t *ring, sentry_level_t level, const char *trace_id, - uint64_t uptime_us, const char *body); + uint64_t uptime_us, const char *body, bool truncated); /** True when there is nothing worth sending, which is the common case between flushes. */ bool sentry_log_ring_empty(const sentry_log_ring_t *ring); diff --git a/src/sentry_micro.c b/src/sentry_micro.c index 4079b91..24a0b98 100644 --- a/src/sentry_micro.c +++ b/src/sentry_micro.c @@ -57,6 +57,8 @@ typedef struct { * so a lifetime counter has to live outside anything a flush resets. */ uint32_t logs_dropped; + /** Lines recorded shorter than intended, since sentry_init() — see sentry_log(). */ + uint32_t logs_truncated; /** * The trace the *previous* boot died inside, recovered from RTC memory. @@ -379,20 +381,37 @@ void sentry_log(sentry_level_t level, const char *message, ...) char body[SENTRY_MICRO_LOG_BODY_LEN]; va_list args; va_start(args, message); - vsnprintf(body, sizeof(body), message, args); + /* vsnprintf() returns how long the formatted result *would have been*, not how much fit + * — the only place that information exists, since a caller downstream only ever sees + * the already-truncated body and cannot recover it. */ + int written = vsnprintf(body, sizeof(body), message, args); va_end(args); + bool truncated = written < 0 || (size_t)written >= sizeof(body); + if (truncated && g_state.logs_truncated < UINT32_MAX) { + g_state.logs_truncated++; + } /* Recorded verbatim, or empty if nothing is active — resolved to a fallback only at * flush time. This is what lets a line written during a real operation stay attached to * it even if the operation has ended by the time the ring is serialised. */ if (sentry_log_ring_push(&g_state.log_ring, level, - g_state.trace.active ? g_state.trace.trace_id : "", sentry_device_uptime_us(), body)) { + g_state.trace.active ? g_state.trace.trace_id : "", sentry_device_uptime_us(), body, + truncated)) { g_state.logs_dropped++; } } uint32_t sentry_logs_dropped_count(void) { return g_state.logs_dropped; } +/** + * Lines recorded shorter than intended, since sentry_init(). + * + * A device with no network still narrates this the way debug_log() would; once one does + * reach Sentry, the same information rides along on the line itself as the `truncated` + * attribute, so a fleet-wide answer does not require polling every device serially. + */ +uint32_t sentry_logs_truncated_count(void) { return g_state.logs_truncated; } + /** * Send whatever has accumulated in the log ring, if anything has. * diff --git a/src/sentry_micro.h b/src/sentry_micro.h index bc2ce4c..0f4a7d9 100644 --- a/src/sentry_micro.h +++ b/src/sentry_micro.h @@ -451,7 +451,11 @@ uint32_t sentry_metrics_dropped_count(void); * console is the point even when nothing else is going on — just without that attachment. * * `message` is formatted (printf-style) into a fixed buffer and truncated to fit; formatting - * a message that is about to be truncated is cheaper than growing the ring to avoid it. + * a message that is about to be truncated is cheaper than growing the ring to avoid it. A + * truncated line is still sent, not dropped — it carries its own `t7d` attribute (`true`) + * so that is visible on the line itself, omitted on the lines that fit rather than spending + * bytes on every line to say so, and counted in `sentry_logs_truncated_count()` before it + * ever reaches Sentry. * * The ring holds `SENTRY_MICRO_MAX_LOGS` lines and evicts the oldest once full — unlike the * metrics table, there is no running total to protect here, so the newest line displacing @@ -470,6 +474,12 @@ void sentry_log(sentry_level_t level, const char *message, ...); */ uint32_t sentry_logs_dropped_count(void); +/** + * Lines recorded shorter than intended, since `sentry_init()` — see the `t7d` attribute on + * the line itself for which one, once it reaches Sentry. + */ +uint32_t sentry_logs_truncated_count(void); + /** * Report a message — the ordinary, non-crash way to tell Sentry something happened. * diff --git a/src/sentry_micro.hpp b/src/sentry_micro.hpp index 3fc86d7..1a61af4 100644 --- a/src/sentry_micro.hpp +++ b/src/sentry_micro.hpp @@ -151,6 +151,25 @@ inline void metric_gauge(const char *name, int64_t value, const char *unit = nul /** Metric names dropped because the table was full. */ inline uint32_t metrics_dropped() { return sentry_metrics_dropped_count(); } +/** + * Record one console line, printf-style. Does not send; rides the next flush. + * + * A plain forwarding template, not a checked one: `sentry_log()`'s own vsnprintf() already + * truncates safely and reports it (see `logs_truncated()` and the `truncated` attribute on + * the line itself), so there is nothing left for this wrapper to add by re-deriving that at + * compile time. + */ +template inline void log(sentry_level_t level, const char *message, Args... args) +{ + sentry_log(level, message, args...); +} + +/** Lines evicted from the ring before they were ever sent. */ +inline uint32_t logs_dropped() { return sentry_logs_dropped_count(); } + +/** Lines recorded shorter than intended. */ +inline uint32_t logs_truncated() { return sentry_logs_truncated_count(); } + /** Captured messages dropped by the local throttle since init. */ inline uint32_t suppressed_count() { return sentry_suppressed_count(); } diff --git a/test/test_log/test_log.c b/test/test_log/test_log.c index 47816ff..a341451 100644 --- a/test/test_log/test_log.c +++ b/test/test_log/test_log.c @@ -28,7 +28,7 @@ static void test_a_line_is_recorded(void) sentry_log_ring_reset(&r); TEST_ASSERT_TRUE(sentry_log_ring_empty(&r)); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "boot complete"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "boot complete", false); TEST_ASSERT_FALSE(sentry_log_ring_empty(&r)); TEST_ASSERT_EQUAL_UINT(1, r.count); TEST_ASSERT_EQUAL_STRING("boot complete", r.entries[0].body); @@ -41,8 +41,8 @@ static void test_lines_are_not_aggregated(void) sentry_log_ring_reset(&r); /* Unlike a metric, two identical bodies are two entries, not one accumulated total. */ - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "tick"); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 2000, "tick"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "tick", false); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 2000, "tick", false); TEST_ASSERT_EQUAL_UINT(2, r.count); } @@ -55,17 +55,18 @@ static void test_a_full_ring_evicts_the_oldest_not_the_newest(void) for (int i = 0; i < SENTRY_MICRO_MAX_LOGS; i++) { snprintf(body, sizeof(body), "line-%d", i); TEST_ASSERT_FALSE( - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, (uint64_t)i * 1000, body)); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, (uint64_t)i * 1000, body, false)); } TEST_ASSERT_EQUAL_UINT(SENTRY_MICRO_MAX_LOGS, r.count); TEST_ASSERT_EQUAL_UINT(0, r.dropped); - /* One more evicts line-0, not line-7: the newest line is worth more than the one it - * replaces, unlike a metrics table protecting a running total. The return value is the - * production signal sentry_log()/logs_dropped_count() actually depend on — not just the - * ring's own internal counter, which happens to move for the same reason but is a - * separate field. */ - TEST_ASSERT_TRUE(sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 99000, "one-too-many")); + /* One more evicts line-0, not the newest survivor: the newest line is worth more than + * the one it replaces, unlike a metrics table protecting a running total. The return + * value is the production signal sentry_log()/logs_dropped_count() actually depend on + * — not just the ring's own internal counter, which happens to move for the same + * reason but is a separate field. */ + TEST_ASSERT_TRUE( + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 99000, "one-too-many", false)); TEST_ASSERT_EQUAL_UINT(SENTRY_MICRO_MAX_LOGS, r.count); TEST_ASSERT_EQUAL_UINT(1, r.dropped); @@ -81,25 +82,59 @@ static void test_entries_serialise_oldest_first(void) { sentry_log_ring_t r; char body[16]; + char one_more[16]; sentry_log_ring_reset(&r); for (int i = 0; i < SENTRY_MICRO_MAX_LOGS; i++) { snprintf(body, sizeof(body), "line-%d", i); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, (uint64_t)i * 1000, body); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, (uint64_t)i * 1000, body, false); } - /* One more evicts line-0, so the ring now holds line-1..line-8 in that order. */ - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 8000, "line-8"); + /* One more evicts line-0, so the ring now holds line-1..line-N (N = SENTRY_MICRO_MAX_LOGS) + * in that order. */ + snprintf(one_more, sizeof(one_more), "line-%d", SENTRY_MICRO_MAX_LOGS); + sentry_log_ring_push( + &r, SENTRY_LEVEL_INFO, TRACE, (uint64_t)SENTRY_MICRO_MAX_LOGS * 1000, one_more, false); char buf[2048]; - size_t len = sentry_log_envelope_write( - buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 9000, NOW_UNIX_US); + size_t len = sentry_log_envelope_write(buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, + (uint64_t)(SENTRY_MICRO_MAX_LOGS + 1) * 1000, NOW_UNIX_US); TEST_ASSERT_TRUE(len > 0 && len < sizeof(buf)); - const char *p2 = strstr(buf, "\"line-2\""); - const char *p8 = strstr(buf, "\"line-8\""); - TEST_ASSERT_NOT_NULL(p2); - TEST_ASSERT_NOT_NULL(p8); - TEST_ASSERT_TRUE(p2 < p8); + /* line-1 is the oldest survivor; the one just pushed is the newest — oldest-first means + * line-1 has to appear before it, regardless of how many entries the ring holds. */ + char expect_oldest[16]; + snprintf(expect_oldest, sizeof(expect_oldest), "\"line-1\""); + const char *p_oldest = strstr(buf, expect_oldest); + char expect_newest[24]; + snprintf(expect_newest, sizeof(expect_newest), "\"%s\"", one_more); + const char *p_newest = strstr(buf, expect_newest); + TEST_ASSERT_NOT_NULL(p_oldest); + TEST_ASSERT_NOT_NULL(p_newest); + TEST_ASSERT_TRUE(p_oldest < p_newest); +} + +static void test_a_full_ring_of_worst_case_entries_fits_the_envelope_budget(void) +{ + sentry_log_ring_t r; + char max_body[SENTRY_MICRO_LOG_BODY_LEN]; + sentry_log_ring_reset(&r); + + /* The scenario that actually matters in production: a full ring of maximum-length + * bodies, every one of them truncated (the expensive case for the conditional `t7d` + * attribute), with a device_id to attach. sentry_log_envelope_write() writes into + * exactly SENTRY_MICRO_ENVELOPE_BUFFER_BYTES in flush_logs() — this is the number that + * has to stay under that budget, not any of the short-body cases the other tests use, + * which would not have caught SENTRY_MICRO_MAX_LOGS/attribute-size regressions here. */ + memset(max_body, 'x', sizeof(max_body) - 1); + max_body[sizeof(max_body) - 1] = '\0'; + for (int i = 0; i < SENTRY_MICRO_MAX_LOGS; i++) { + sentry_log_ring_push(&r, SENTRY_LEVEL_WARNING, TRACE, (uint64_t)i * 1000, max_body, true); + } + + size_t needed + = sentry_log_envelope_write(NULL, 0, &r, FALLBACK_TRACE, DEVICE_ID, 100000, NOW_UNIX_US); + TEST_ASSERT_TRUE(needed > 0); + TEST_ASSERT_TRUE(needed <= SENTRY_MICRO_ENVELOPE_BUFFER_BYTES); } static void test_an_overlong_body_is_truncated_not_dropped(void) @@ -110,19 +145,23 @@ static void test_an_overlong_body_is_truncated_not_dropped(void) memset(long_body, 'x', sizeof(long_body) - 1); long_body[sizeof(long_body) - 1] = '\0'; - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, long_body); + /* Caller passes false — it never called vsnprintf and has no idea this was too long — + * but the ring's own copy has to truncate it regardless, and that has to be visible on + * the entry even though nobody upstream reported it. */ + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, long_body, false); TEST_ASSERT_EQUAL_UINT(1, r.count); /* Truncated to fit, not rejected: a shortened line the operator can still read beats * losing it entirely. */ TEST_ASSERT_EQUAL_UINT(SENTRY_MICRO_LOG_BODY_LEN - 1, strlen(r.entries[0].body)); + TEST_ASSERT_TRUE(r.entries[0].truncated); } static void test_recorded_trace_id_wins_over_the_fallback(void) { sentry_log_ring_t r; sentry_log_ring_reset(&r); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "during a real operation"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "during a real operation", false); char buf[2048]; size_t len = sentry_log_envelope_write( @@ -137,7 +176,7 @@ static void test_an_idle_recorded_line_falls_back_to_the_batch_trace(void) sentry_log_ring_t r; sentry_log_ring_reset(&r); /* Empty trace_id: nothing was active when this line was recorded. */ - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, "", 1000, "while idle"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, "", 1000, "while idle", false); char buf[2048]; size_t len = sentry_log_envelope_write( @@ -150,8 +189,8 @@ static void test_a_batch_may_mix_entries_from_different_traces(void) { sentry_log_ring_t r; sentry_log_ring_reset(&r); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "during the operation"); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, "", 2000, "after it ended"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "during the operation", false); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, "", 2000, "after it ended", false); char buf[2048]; size_t len = sentry_log_envelope_write( @@ -167,7 +206,7 @@ static void test_writes_a_log_envelope(void) char buf[2048]; sentry_log_ring_reset(&r); - sentry_log_ring_push(&r, SENTRY_LEVEL_WARNING, TRACE, 1000, "reconnect attempt 3"); + sentry_log_ring_push(&r, SENTRY_LEVEL_WARNING, TRACE, 1000, "reconnect attempt 3", false); size_t len = sentry_log_envelope_write( buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 501000, NOW_UNIX_US); @@ -182,8 +221,10 @@ static void test_writes_a_log_envelope(void) TEST_ASSERT_NULL(strstr(buf, "\"level\":\"warning\"")); TEST_ASSERT_NOT_NULL(strstr(buf, "\"severity_number\":13")); TEST_ASSERT_NOT_NULL(strstr(buf, "\"trace_id\":\"" TRACE "\"")); - TEST_ASSERT_NOT_NULL(strstr( - buf, "\"attributes\":{\"device_id\":{\"value\":\"" DEVICE_ID "\",\"type\":\"string\"}}")); + /* Not truncated, so `t7d` is omitted entirely rather than written as false. */ + TEST_ASSERT_NULL(strstr(buf, "\"t7d\"")); + TEST_ASSERT_NOT_NULL( + strstr(buf, "\"attributes\":{\"d_id\":{\"value\":\"" DEVICE_ID "\",\"type\":\"string\"}}")); /* Entry recorded 500ms of uptime before the flush anchor: its timestamp is the flush's * wall-clock anchor minus that same 500ms, not the flush time itself. */ @@ -199,7 +240,7 @@ static void test_entry_unix_us_clamps_instead_of_underflowing(void) * elapsed clamps to 0 rather than underflowing — the entry reads as "now", not as a * huge wrapped uint64. */ sentry_log_ring_reset(&r); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 5000, "x"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 5000, "x", false); TEST_ASSERT_TRUE(sentry_log_envelope_write( buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 1000, NOW_UNIX_US) > 0); @@ -209,7 +250,7 @@ static void test_entry_unix_us_clamps_instead_of_underflowing(void) * device has decades of continuous uptime — but the arithmetic must not wrap) clamps to * the flush's own anchor instead of underflowing past it. */ sentry_log_ring_reset(&r); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 0, "x"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 0, "x", false); TEST_ASSERT_TRUE(sentry_log_envelope_write(buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, NOW_UNIX_US + 1000000, NOW_UNIX_US) > 0); @@ -220,7 +261,7 @@ static void test_envelope_write_reports_the_size_it_needs(void) { sentry_log_ring_t r; sentry_log_ring_reset(&r); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "boot complete"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "boot complete", false); /* Dry run, then a real one that must agree. */ size_t needed @@ -261,7 +302,7 @@ static void test_every_level_maps_to_its_log_name_and_severity(void) char expect_level[32]; char expect_severity[32]; sentry_log_ring_reset(&r); - sentry_log_ring_push(&r, cases[i].level, TRACE, 1000, "x"); + sentry_log_ring_push(&r, cases[i].level, TRACE, 1000, "x", false); size_t len = sentry_log_envelope_write( buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 1000, NOW_UNIX_US); @@ -291,7 +332,7 @@ static void test_no_clock_means_no_envelope(void) sentry_log_ring_t r; char buf[2048]; sentry_log_ring_reset(&r); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "x"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "x", false); /* Held, not dropped: the caller keeps the ring and tries again once the device has been * told the date, the same reasoning as metrics. */ @@ -305,7 +346,7 @@ static void test_no_fallback_trace_means_no_envelope(void) sentry_log_ring_t r; char buf[2048]; sentry_log_ring_reset(&r); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "x"); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "x", false); TEST_ASSERT_EQUAL_UINT( 0, sentry_log_envelope_write(buf, sizeof(buf), &r, "", DEVICE_ID, 2000, NOW_UNIX_US)); @@ -313,12 +354,33 @@ static void test_no_fallback_trace_means_no_envelope(void) 0, sentry_log_envelope_write(buf, sizeof(buf), &r, NULL, DEVICE_ID, 2000, NOW_UNIX_US)); } -static void test_a_missing_device_id_omits_attributes_not_the_envelope(void) +static void test_a_missing_device_id_omits_it_not_the_attributes(void) { sentry_log_ring_t r; char buf[2048]; sentry_log_ring_reset(&r); - sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "x"); + /* truncated=true so `attributes` has something to say regardless of device_id — this + * isolates what omitting the device_id specifically does, from whether `attributes` + * appears at all. */ + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "x", true); + + size_t len + = sentry_log_envelope_write(buf, sizeof(buf), &r, FALLBACK_TRACE, NULL, 2000, NOW_UNIX_US); + TEST_ASSERT_TRUE(len > 0); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"attributes\"")); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"t7d\"")); + TEST_ASSERT_NULL(strstr(buf, "\"d_id\"")); +} + +static void test_attributes_is_omitted_when_nothing_applies(void) +{ + sentry_log_ring_t r; + char buf[2048]; + sentry_log_ring_reset(&r); + /* Neither truncated nor a device_id to report — the whole key is skipped rather than + * written as an empty object, since an envelope's worth of these is billed against the + * same budget a full ring of long lines is already close to. */ + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "x", false); size_t len = sentry_log_envelope_write(buf, sizeof(buf), &r, FALLBACK_TRACE, NULL, 2000, NOW_UNIX_US); @@ -326,15 +388,39 @@ static void test_a_missing_device_id_omits_attributes_not_the_envelope(void) TEST_ASSERT_NULL(strstr(buf, "\"attributes\"")); } +static void test_the_t7d_attribute_reflects_what_actually_happened(void) +{ + sentry_log_ring_t r; + char buf[2048]; + + /* A line the caller knows fit fine: t7d is omitted, not written as false, since the + * common case should not spend bytes saying nothing went wrong. */ + sentry_log_ring_reset(&r); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "short", false); + TEST_ASSERT_TRUE(sentry_log_envelope_write( + buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 2000, NOW_UNIX_US) + > 0); + TEST_ASSERT_NULL(strstr(buf, "\"t7d\"")); + + /* A line the caller already knows was cut short upstream — e.g. sentry_log()'s own + * vsnprintf() reported it would have been longer than the buffer it formatted into. */ + sentry_log_ring_reset(&r); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, "short", true); + TEST_ASSERT_TRUE(sentry_log_envelope_write( + buf, sizeof(buf), &r, FALLBACK_TRACE, DEVICE_ID, 2000, NOW_UNIX_US) + > 0); + TEST_ASSERT_NOT_NULL(strstr(buf, "\"t7d\":{\"value\":true,\"type\":\"boolean\"}")); +} + static void test_null_is_safe(void) { TEST_ASSERT_TRUE(sentry_log_ring_empty(NULL)); sentry_log_ring_reset(NULL); - TEST_ASSERT_FALSE(sentry_log_ring_push(NULL, SENTRY_LEVEL_INFO, TRACE, 1000, "x")); + TEST_ASSERT_FALSE(sentry_log_ring_push(NULL, SENTRY_LEVEL_INFO, TRACE, 1000, "x", false)); sentry_log_ring_t r; sentry_log_ring_reset(&r); - TEST_ASSERT_FALSE(sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, NULL)); + TEST_ASSERT_FALSE(sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 1000, NULL, false)); TEST_ASSERT_TRUE(sentry_log_ring_empty(&r)); } @@ -345,6 +431,7 @@ int main(void) RUN_TEST(test_lines_are_not_aggregated); RUN_TEST(test_a_full_ring_evicts_the_oldest_not_the_newest); RUN_TEST(test_entries_serialise_oldest_first); + RUN_TEST(test_a_full_ring_of_worst_case_entries_fits_the_envelope_budget); RUN_TEST(test_an_overlong_body_is_truncated_not_dropped); RUN_TEST(test_recorded_trace_id_wins_over_the_fallback); RUN_TEST(test_an_idle_recorded_line_falls_back_to_the_batch_trace); @@ -356,7 +443,9 @@ int main(void) RUN_TEST(test_an_empty_ring_writes_nothing); RUN_TEST(test_no_clock_means_no_envelope); RUN_TEST(test_no_fallback_trace_means_no_envelope); - RUN_TEST(test_a_missing_device_id_omits_attributes_not_the_envelope); + RUN_TEST(test_a_missing_device_id_omits_it_not_the_attributes); + RUN_TEST(test_attributes_is_omitted_when_nothing_applies); + RUN_TEST(test_the_t7d_attribute_reflects_what_actually_happened); RUN_TEST(test_null_is_safe); return UNITY_END(); } From 6e912fc908842440a7485989c95006b805b61a6d Mon Sep 17 00:00:00 2001 From: Giovanni M Guidini Date: Thu, 20 Aug 2026 17:03:11 +0200 Subject: [PATCH 4/7] wifi_basic: trace the WiFi connect and a demo crash, log through both MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds three sentry_log() lines and two sentry::Transaction traces to make the Logs feature visible end to end on real hardware, not just in host tests: - One line recorded before any trace exists this boot (right after print_sentry_state()), landing in Sentry with no trace_id — the idle case sentry_log()'s own doc describes. - connect_wifi() itself gains two lines, one per outcome, with no trace object threaded through it: they inherit whatever trace is active on the call stack, which is exactly what a new "wifi-connect" transaction wrapping the call in setup() provides. sentry_transaction_start() mints that trace itself since none exists yet. - A third line, level FATAL, right before the demo crash under SENTRY_DEMO_CRASH, wrapped in its own "demo-crash" transaction that is deliberately never finished — the device is about to end the boot, so there is no operation left to time. What the transaction leaves behind is a trace that is still active when the crash happens, which sentry_event_attach_coredump() picks up on the next boot and joins the recovered event to, the same way a request handler's trace would join a crash that happened while it was running. Getting this right took three real fixes along the way, not just adding the calls: - The wifi-connect transaction needs a synced clock to keep itself at all (sentry_transaction_finish() drops a transaction with none), and the very WiFi connection it traces is what makes that sync possible — reordered so sync_time() runs, and the transport is registered, before the transaction tries to finish rather than after. - sentry_transaction_finish() ends a transaction but not the trace it rode. Left active, the wifi-connect trace would have silently welded the boot report and the demo-crash trace to an unrelated WiFi connection. Released explicitly once the transaction is done. - loop()'s only sentry_flush() call was gated on sentry_buffered_count(), which tracks the offline retry buffer only. Metrics and logs accumulate independently of that buffer and were never being flushed at all in the common case of nothing ever landing in it — this predates the Logs feature but nothing exercised the gap until now. Also added an explicit flush before the demo crash itself, since loop() never runs again to do it on its own interval. 153 host tests pass; all four chip variants build clean, with and without -D SENTRY_DEMO_CRASH=1. --- examples/wifi_basic/src/main.cpp | 80 ++++++++++++++++++++++++++------ 1 file changed, 65 insertions(+), 15 deletions(-) diff --git a/examples/wifi_basic/src/main.cpp b/examples/wifi_basic/src/main.cpp index a20f6ed..648c9ff 100644 --- a/examples/wifi_basic/src/main.cpp +++ b/examples/wifi_basic/src/main.cpp @@ -200,12 +200,19 @@ static bool connect_wifi() if (WiFi.status() != WL_CONNECTED) { Serial.printf("[wifi] failed after %lums (status %d)\n", (unsigned long)(millis() - started), (int)WiFi.status()); + /* Called from inside whatever trace the caller started (see setup()) — sentry_log() + * reads that state itself, so this line needs no trace argument to end up attached + * to it. */ + sentry::log(SENTRY_LEVEL_WARNING, "WiFi connect failed after %lums (status %d)", + (unsigned long)(millis() - started), (int)WiFi.status()); report_visible_networks(); return false; } Serial.printf("[wifi] connected: ip=%s rssi=%ddBm in %lums\n", WiFi.localIP().toString().c_str(), (int)WiFi.RSSI(), (unsigned long)(millis() - started)); + sentry::log(SENTRY_LEVEL_INFO, "WiFi connected: ip=%s rssi=%ddBm in %lums", + WiFi.localIP().toString().c_str(), (int)WiFi.RSSI(), (unsigned long)(millis() - started)); return true; } @@ -500,6 +507,11 @@ void setup() print_sentry_state(); + /* Recorded before any trace exists this boot — see sentry_log()'s doc for why an idle + * line is still held and sent. Compare with the line inside connect_wifi() below, + * recorded once the wifi-connect trace is active. */ + sentry::log(SENTRY_LEVEL_INFO, "%s starting on %s", FIRMWARE_RELEASE, BOARD_NAME); + #if SENTRY_DEMO_SCAN /* Build with -D SENTRY_DEMO_SCAN=1 to list what the radio can see on every boot, * whether or not the connect succeeds. Normally this only runs after a failure, which @@ -527,23 +539,44 @@ void setup() #endif /* - * Join WiFi if possible — connect_wifi() prints the outcome either way, and runs a - * scan diagnostic on failure. Its return value now only gates the first attempt at the - * time sync (NTP needs a route); it is not used to pick a transport, unlike before: - * `transport` (file scope, declared above) already tries WiFi first and falls back to - * the serial relay on every delivery attempt, re-evaluated fresh each time — so a WiFi - * connection that comes up *after* this point still gets used for sending. Getting a - * synced clock the same way needs the explicit retry in loop() below: unlike picking a - * transport, sync_time() is not something `transport` redoes on every attempt on its - * own. + * Registered before WiFi has necessarily even connected, not after: the wifi-connect + * transaction below tries to send the moment it finishes, and `transport` is what + * makes that possible rather than something merely buffered for later. AutoTransport + * re-picks a route on every attempt regardless of when it was registered, so there is + * no reason to wait for a connection first. */ - if (connect_wifi()) { - time_synced = sync_time(); - } sentry::set_transport(transport); Serial.println("[sentry] transport: auto (wifi with tls verification, falling back to " "the serial relay — run scripts/serial_relay.py if wifi is unreachable)"); + /* + * Join WiFi if possible — connect_wifi() prints the outcome either way, and runs a + * scan diagnostic on failure. Wrapped in its own transaction so the attempt is a traced + * operation with a duration in Sentry, and so connect_wifi()'s own sentry_log() call + * lands attached to it rather than to nothing — sentry_transaction_start() starts a + * trace itself when none is active yet, which is what makes that attachment happen + * with no trace object threaded through connect_wifi(). + * + * The clock sync happens *before* the transaction is finished, not just before it + * gates `time_synced` for loop()'s retry below: sentry_transaction_finish() needs a + * synced clock to keep this transaction at all (see its doc), and the very first WiFi + * connection of a boot is exactly the operation that makes a sync possible in the + * first place. Finishing after it, rather than before, is what lets + * this specific transaction get a real timestamp instead of being dropped every time. + */ + sentry::Transaction wifi_txn; + sentry::transaction_start(wifi_txn, "wifi-connect", "device.operation"); + bool wifi_connected = connect_wifi(); + if (wifi_connected) { + time_synced = sync_time(); + } + sentry::transaction_finish(wifi_txn); + /* Released, not left active: sentry_transaction_finish() ends the transaction but not + * the trace it rode, and anything reported past this point — the boot event below, a + * later demo crash — has nothing to do with this WiFi connection. Leaving it active + * would weld those unrelated events to it instead of leaving them untraced. */ + sentry::trace_release(); + /* A recovered crash is the more interesting event, and reporting both on the same boot * would double up. */ if (!report_crash()) { @@ -559,6 +592,22 @@ void setup() * one crash-and-report cycle instead of an endless loop. */ if (!sentry_reset_reason_is_crash(sentry::device_info().reset_reason)) { Serial.println("\n[demo] crashing deliberately in 3s ..."); + /* + * A trace, not a transaction that ever finishes: demo_crash_outer() ends the boot, + * so there is no operation left to time or send. What matters is that a trace is + * active when it dies — sentry_event_attach_coredump() (see report_crash(), next + * boot) reads whatever trace was active at the moment of the crash and joins the + * recovered event to it, the same way a request handler's trace would join a crash + * that happened while it was running. + */ + sentry::Transaction crash_txn; + sentry::transaction_start(crash_txn, "demo-crash", "device.operation"); + sentry::log(SENTRY_LEVEL_FATAL, "Deliberately crashing in demo_crash_outer() in 3s"); + /* sentry_log() only writes into the ring — see its doc — and demo_crash_outer() + * below ends the boot before loop() ever runs again to flush it on its own + * interval. Flushed explicitly here so the line this demo exists to show actually + * leaves the device instead of being zeroed with the rest of RAM on reset. */ + sentry_flush(4); delay(3000); demo_crash_outer(); } @@ -583,14 +632,15 @@ void loop() /* Once a minute, show that the device is alive and what its resources look like — * the same numbers that will ride along on every event as device context. */ - /* Retry anything the buffer is holding — this is how an event created before the radio - * came up eventually gets out. + /* Not gated on sentry_buffered_count(): that only tracks the offline retry buffer — + * see sentry_flush()'s own comment for why metrics and logs need this call regardless + * of buffer state. * * On an interval, not every iteration: a transport can block for seconds when there is * no route (the serial relay waits for a host that may not be listening), so flushing * every pass would turn `loop()` into a chain of timeouts. */ static uint32_t last_flush = 0; - if (sentry_buffered_count() > 0 && millis() - last_flush >= 30000) { + if (millis() - last_flush >= 30000) { last_flush = millis(); sentry_flush(2); } From bd5b3d700cbd9808af8a12bb511da2a7cab23228 Mon Sep 17 00:00:00 2001 From: Giovanni M Guidini Date: Thu, 20 Aug 2026 17:21:23 +0200 Subject: [PATCH 5/7] wifi_basic: give loopTask enough stack to hold a transaction across TLS MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Confirmed on real hardware (esp32dev): holding a sentry::Transaction open across the wifi-connect send overflows Arduino's default 8 KB loop task stack every time, deterministically, right inside the TLS handshake's entropy gathering. A sentry_transaction_t plus sentry_transaction_finish()'s 2 KB envelope buffer sit on setup()'s stack frame the whole time WiFiClientSecure is also using several KB of its own for mbedtls_ctr_drbg_seed() — nothing in this example ever exercised that combination before, since the only prior sends came from capture_message(), with no transaction alive at the same time. -D CONFIG_ARDUINO_LOOP_STACK_SIZE= looked like the fix but silently does nothing: sdkconfig.h #defines that macro unconditionally, after the command line runs, and wins. Verified this the hard way — objdump on the built ELF showed getArduinoLoopTaskStackSize() still returning 8192 with the flag set, and the crash persisted identically even after doubling the requested size. Overriding the weak getArduinoLoopTaskStackSize() symbol that cores/esp32/main.cpp declares specifically for this is the documented, actually-effective path — confirmed via nm/objdump that the override links as the sole strong definition and returns 16384. Confirmed fixed on real hardware: the wifi-connect transaction, and the sentry_log() lines riding the boot-start and connect_wifi() logs, now deliver over WiFi/TLS without crashing, both when the clock syncs before the transaction tries to finish and (that case being timing-dependent) the documented drop when it does not. --- examples/wifi_basic/src/main.cpp | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/examples/wifi_basic/src/main.cpp b/examples/wifi_basic/src/main.cpp index 648c9ff..b7ec171 100644 --- a/examples/wifi_basic/src/main.cpp +++ b/examples/wifi_basic/src/main.cpp @@ -456,6 +456,22 @@ static void demo_flood() } #endif +/** + * Arduino-ESP32 declares this `weak` in cores/esp32/main.cpp specifically so a sketch can + * override it; the 8 KB default it otherwise returns is not this example's call to make. + * + * A `sentry_transaction_t` plus sentry_transaction_finish()'s 2 KB envelope buffer (see + * core/sentry_span.h for that measured SDK-side cost) sit on setup()'s stack frame across + * the wifi-connect transaction, which then calls into WiFiClientSecure for the send itself + * — a TLS handshake that needs several more KB of its own for mbedtls_ctr_drbg_seed()'s + * entropy gathering. Confirmed on real hardware: 8 KB overflows (stack canary watchpoint + * triggered) the first time this example holds a transaction open across that send, and + * setting CONFIG_ARDUINO_LOOP_STACK_SIZE via a build flag does not change it — sdkconfig.h + * `#define`s that macro unconditionally, after the command line, and wins. 16 KB leaves + * real headroom rather than a number tuned to just survive one measurement. + */ +size_t getArduinoLoopTaskStackSize(void) { return 16384; } + void setup() { Serial.begin(115200); From a66e207f98eb47884ec64550aa63f65f7d96b2a5 Mon Sep 17 00:00:00 2001 From: Giovanni M Guidini Date: Thu, 20 Aug 2026 17:24:08 +0200 Subject: [PATCH 6/7] CHANGELOG: add entries for Logs, the buffer bump, and the stack-size fix Covers the work already committed on this branch: the offline buffer growing to 16 slots, the Logs feature itself (ring, truncation, the t7d/d_id byte-budget fix), tracing added to wifi_basic, the periodic-flush gate bug that fix exposed, and the loop-task stack-size fix needed to hold a transaction open across a real TLS send. --- CHANGELOG.md | 41 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 41 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index f664a9b..9157172 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -276,3 +276,44 @@ clock: they do, and until the device has been told the date the table keeps accumulating rather than being dropped — a counter over a longer interval is still true, unlike a stale duration. +- Offline buffer grown from 8 to 16 slots in both examples, and documented how to size + `slots`: `sentry_storage_nvs()` already accepted any count from 1 to `SENTRY_NVS_MAX_SLOTS` + (64), a smaller firmware should pass a smaller one. Still one shared ring across every + envelope type with no priority tier — the fix for a high-volume category evicting + something that mattered more is a transport that keeps delivering, not triage over whose + envelope keeps its slot. +- Logs: `sentry_log()` / `sentry::log()`, a fixed-size ring of `SENTRY_MICRO_MAX_LOGS` + console lines emitted as a `log` envelope item. Unlike a metric, each line remembers + whatever trace was active when it was recorded rather than whatever is active at flush + time — a line written during a real operation stays attached to it, the same way a + breadcrumb would. A line recorded while idle is still held and sent, just without that + attachment; logging the console is the point even when nothing else is going on. +- Each log line tracks its own truncation from `vsnprintf()`'s actual return value rather + than predicting it at compile time — exact instead of a conservative worst-case bound, and + it works for a runtime format string too. Surfaced as a persistent + `sentry_logs_truncated_count()` and a per-line `t7d` attribute, present only when true. + `sentry_logs_dropped_count()` persists since `sentry_init()` rather than resetting every + flush, matching `sentry_metrics_dropped_count()`'s own contract. +- A full ring of realistic-length log lines did not fit in + `SENTRY_MICRO_ENVELOPE_BUFFER_BYTES`, even before the truncation attribute existed — + `flush_logs()` would have silently refused to send and left the ring stuck indefinitely. + Fixed by abbreviating attribute keys (`truncated` → `t7d`, `device_id` → `d_id`), making + both keys — and the `attributes` object itself — conditional, and lowering + `SENTRY_MICRO_MAX_LOGS` from 8 to 6. +- `wifi_basic` now traces the WiFi connect attempt and a deliberate demo crash + (`-D SENTRY_DEMO_CRASH=1`), with `sentry_log()` calls riding both: one line recorded + before any trace exists this boot carries no `trace_id`, one recorded during the + wifi-connect transaction does. The crash-demo transaction is deliberately never + finished — the trace it leaves active is what `sentry_event_attach_coredump()` joins the + recovered crash event to on the next boot. +- `wifi_basic`'s periodic flush in `loop()` was gated on `sentry_buffered_count() > 0`, + which only tracks the offline retry buffer. Metrics and logs accumulate independently of + that buffer and were never actually being flushed in the common case of nothing ever + landing in it — a pre-existing gap since the buffering example was written, unnoticed + until logs needed the ring to ever go out. Flush is no longer gated on it. +- Holding a live `sentry::Transaction` open across a WiFi/TLS send overflows Arduino's + default 8 KB loop task stack, confirmed on real hardware. + `-D CONFIG_ARDUINO_LOOP_STACK_SIZE=` looks like the fix but does nothing: `sdkconfig.h` + redefines that macro unconditionally after the command line and wins. `wifi_basic` now + overrides Arduino-ESP32's own `getArduinoLoopTaskStackSize()` `weak` hook instead, raising + the stack to 16 KB. From a5da9d5da543dcc3f2fecb5cda005bea528af0d6 Mon Sep 17 00:00:00 2001 From: Giovanni M Guidini Date: Thu, 20 Aug 2026 17:51:38 +0200 Subject: [PATCH 7/7] Logs and Metrics: compile-time opt-out, matching the TLS toggle Both the log ring and the metrics table were permanent g_state fields with no way to get the RAM back, unlike a transaction's spans: a metric or a log line has to survive across flushes rather than living on a caller's stack for one operation, so neither was ever caller-owned. Nothing else in this SDK reserves storage a build cannot opt out of. SENTRY_MICRO_LOGS_ENABLED and SENTRY_MICRO_METRICS_ENABLED (both default 1) follow the exact SENTRY_MICRO_WIFI_TLS precedent already in this codebase: setting either to 0 removes the field, the recording functions, the dropped- count getters and flush_logs()/flush_metrics(), rather than turning them into no-ops. A build that disables a feature and still calls into it fails to compile, the same way set_ca_cert() disappears under SENTRY_MICRO_WIFI_TLS=0 -- silently doing nothing would be a worse failure mode than a build error. Measured on esp32dev, a wifi_basic build that never calls either API: RAM Flash Logs 832 B 1,496 B Metrics 272 B 1,140 B Both 1,104 B 3,056 B README gains a "Logs" section (previously undocumented despite the feature existing) with its own "What it costs" table alongside Spans' and Metrics', and both toggles are cross-referenced from each other. 162 host tests pass; the core log/metrics rings these gate are untouched -- test_log.c/test_metrics.c exercise them directly and never go through the gated sentry_micro.c wiring. All four wifi_basic chip variants build clean at the default (both enabled), and the disabled-but-still-called case was confirmed to fail to compile rather than silently link. --- CHANGELOG.md | 9 +++++ README.md | 69 +++++++++++++++++++++++++++++++++++++++ src/core/sentry_log.h | 21 ++++++++++++ src/core/sentry_metrics.h | 19 +++++++++++ src/sentry_micro.c | 25 ++++++++++++-- src/sentry_micro.h | 10 ++++++ src/sentry_micro.hpp | 4 +++ 7 files changed, 154 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 9157172..22673e3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -317,3 +317,12 @@ redefines that macro unconditionally after the command line and wins. `wifi_basic` now overrides Arduino-ESP32's own `getArduinoLoopTaskStackSize()` `weak` hook instead, raising the stack to 16 KB. +- `SENTRY_MICRO_LOGS_ENABLED=0` and `SENTRY_MICRO_METRICS_ENABLED=0` remove the log ring and + metrics table entirely, the same pattern `SENTRY_MICRO_WIFI_TLS=0` already uses for the + TLS branch. Unlike a transaction's spans, both tables are permanent `g_state` fields — + a metric or a log line has to survive across flushes rather than living on a caller's + stack for one operation — so they cost RAM whether or not firmware ever calls them, with + no way before this to get it back. Measured on `esp32dev`: 832 B RAM / 1,496 B flash for + logs, 272 B RAM / 1,140 B flash for metrics, on a build that never calls either. Disabled + functions are not declared at all rather than becoming no-ops, so a build that turns a + feature off and still calls it fails to compile instead of silently doing nothing. diff --git a/README.md b/README.md index 2f55940..00205cf 100644 --- a/README.md +++ b/README.md @@ -758,6 +758,14 @@ reports it. Integers only, because printf's float support is an opt-in linker flag on this target that firmware routinely leaves off. +**The table costs 272 bytes of permanent RAM whether or not you ever call these** — unlike a +transaction's spans, a metric has to survive across flushes rather than living on a caller's +stack for one operation, so it is a permanent `g_state` field the same way the log ring +below is. `SENTRY_MICRO_METRICS_ENABLED=0` removes it, along with `sentry_metric_count()` / +`sentry_metric_gauge()` / `sentry_metrics_dropped_count()` — see +[Logs](#logs-a-continuous-console-correlated-by-trace) for the measured table; the two +toggles are independent and combine. + ### What it costs | | | @@ -787,6 +795,67 @@ the device the time, which on a BLE-only device may never happen at all on a giv cycle. `sentry-sample_rand` is parsed from `baggage` and carried for later use, but the device honours the caller's sampling decision rather than making its own. +### Logs: a continuous console, correlated by trace + +A deployed device's console is the one thing you most want and cannot have — it is a cable +you are not attached to. `sentry_log()` mirrors it: + +```cpp +sentry::log(SENTRY_LEVEL_WARNING, "WiFi reconnect attempt %u", attempt); +``` + +**Recording does not send, the same as a metric** — it writes into a fixed ring and rides +the next `sentry_flush()`. Unlike a metric, each line remembers whatever trace was active +when it was *recorded*, not whatever happens to be active when the ring is flushed later — +the same way a breadcrumb attaches to what the device was actually doing, rather than to +nothing (or something unrelated) by the time the batch goes out. A line recorded while idle +is still held and sent, just without that attachment: logging the console is the point even +when nothing else is going on. + +The message is formatted printf-style into a fixed `SENTRY_MICRO_LOG_BODY_LEN`-byte buffer +(81 bytes by default, a conventional terminal line width) and truncated to fit rather than +dropped — a shortened line you can still read beats losing it entirely. Truncation is +computed from `vsnprintf()`'s own return value, not predicted at compile time, and reported +two ways: `sentry_logs_truncated_count()` since init, and a per-line `t7d` attribute +(present only when true) once the line reaches Sentry. + +The ring holds `SENTRY_MICRO_MAX_LOGS` lines (6 by default) and evicts the oldest once +full — unlike the metrics table, there is no running total to protect here, so the newest +line displacing the old one is the right trade for a continuous stream. +`sentry_logs_dropped_count()` reports how many were evicted before they were ever sent. + +### What it costs + +| | | +| --- | --- | +| Permanent RAM | **832 B** at the defaults (`sentry_log_ring_t`: 6 × 136-byte entries) | +| Flash, always linked | ~1.5 KB — `flush_logs()` runs on every `sentry_flush()`, whether or not the firmware ever calls `sentry_log()` | + +Unlike a transaction, this is not opt-in by usage: the ring is a permanent `g_state` field, +because a log line — like a metric — has to survive across flushes rather than living on a +caller's stack for one operation. `SENTRY_MICRO_LOGS_ENABLED=0` removes it entirely: + +```ini +build_flags = -D SENTRY_MICRO_LOGS_ENABLED=0 +``` + +Measured on `esp32dev`, a build of `wifi_basic` that never calls `sentry_log()`, with and +without: + +| | Enabled (default) | `SENTRY_MICRO_LOGS_ENABLED=0` | Saved | +| --- | --- | --- | --- | +| Flash | 941,557 B | 940,061 B | 1,496 B | +| RAM | 49,924 B | 49,092 B | 832 B | + +`sentry_log()`, `sentry_logs_dropped_count()` and `sentry_logs_truncated_count()` are not +declared at all when disabled, the same as `set_ca_cert()` under `SENTRY_MICRO_WIFI_TLS=0` +above — a build that turns logs off and still tries to call one fails to compile rather than +silently doing nothing. + +`SENTRY_MICRO_METRICS_ENABLED=0` does the same for Application Metrics (272 B RAM, ~1.1 KB +flash on the same build), and the two toggles combine: **1,104 B RAM and 3,056 B flash** +saved with both off. + ## Writing a transport Everything Sentry-specific has already happened by the time a transport is called: it gets a diff --git a/src/core/sentry_log.h b/src/core/sentry_log.h index 9a4c2e2..2e882b5 100644 --- a/src/core/sentry_log.h +++ b/src/core/sentry_log.h @@ -19,6 +19,27 @@ #include "sentry_envelope.h" /* sentry_level_t */ #include "sentry_trace.h" /* SENTRY_MICRO_TRACE_ID_LEN */ +/** + * Compile the SDK's log ring in (1, the default) or out (0). + * + * The ring below costs nothing on its own — these are plain functions over a struct you + * would own, the same as a span. What costs something unconditionally is + * `sentry_micro.c`'s singleton: it carries one `sentry_log_ring_t` (roughly 800 bytes at the + * defaults) as a permanent `g_state` field, paid in every build whether or not firmware ever + * calls `sentry_log()`, because nothing else there is optional either. Setting this to 0 + * removes that field along with `sentry_log()`, `sentry_logs_dropped_count()` and + * `sentry_logs_truncated_count()`, so a build that does not want the console mirrored does + * not carry the ring that would have held it. + * + * This header's own ring type stays available either way — a caller who wants a log ring + * with different lifetime than the singleton's can still build one directly. + * + * build_flags = -D SENTRY_MICRO_LOGS_ENABLED=0 + */ +#ifndef SENTRY_MICRO_LOGS_ENABLED +# define SENTRY_MICRO_LOGS_ENABLED 1 +#endif + #ifdef __cplusplus extern "C" { #endif diff --git a/src/core/sentry_metrics.h b/src/core/sentry_metrics.h index f848986..52befe1 100644 --- a/src/core/sentry_metrics.h +++ b/src/core/sentry_metrics.h @@ -26,6 +26,25 @@ #include "sentry_boot.h" +/** + * Compile the SDK's metrics table in (1, the default) or out (0). + * + * The table below costs nothing on its own — plain functions over a struct you would own, + * the same as a span. What costs something unconditionally is `sentry_micro.c`'s singleton: + * it carries one `sentry_metrics_t` (roughly 250 bytes at the defaults) as a permanent + * `g_state` field, paid in every build whether or not firmware ever calls + * `sentry_metric_count()` / `sentry_metric_gauge()`. Setting this to 0 removes that field + * along with those two functions and `sentry_metrics_dropped_count()`, so a build that never + * counts anything does not carry the table that would have held it. + * + * This header's own table type stays available either way. + * + * build_flags = -D SENTRY_MICRO_METRICS_ENABLED=0 + */ +#ifndef SENTRY_MICRO_METRICS_ENABLED +# define SENTRY_MICRO_METRICS_ENABLED 1 +#endif + #ifdef __cplusplus extern "C" { #endif diff --git a/src/sentry_micro.c b/src/sentry_micro.c index 24a0b98..f2767e1 100644 --- a/src/sentry_micro.c +++ b/src/sentry_micro.c @@ -42,12 +42,18 @@ typedef struct { /** * Numbers accumulated between flushes. About 200 bytes, and unlike a transaction this * has to live across calls — a counter that reset every time nobody was looking would - * count nothing. + * count nothing. Absent entirely when built with SENTRY_MICRO_METRICS_ENABLED=0. */ +#if SENTRY_MICRO_METRICS_ENABLED sentry_metrics_t metrics; uint32_t metrics_dropped; +#endif - /** Console lines accumulated between flushes. See core/sentry_log.h. */ + /** + * Console lines accumulated between flushes. See core/sentry_log.h. Absent entirely + * when built with SENTRY_MICRO_LOGS_ENABLED=0. + */ +#if SENTRY_MICRO_LOGS_ENABLED sentry_log_ring_t log_ring; /** * Lines evicted from the ring since sentry_init(), persistent across flushes. @@ -59,6 +65,7 @@ typedef struct { uint32_t logs_dropped; /** Lines recorded shorter than intended, since sentry_init() — see sentry_log(). */ uint32_t logs_truncated; +#endif /** * The trace the *previous* boot died inside, recovered from RTC memory. @@ -357,6 +364,7 @@ size_t sentry_trace_header(char *buf, size_t cap) return sentry_trace_header_write(buf, cap, &g_state.trace); } +#if SENTRY_MICRO_METRICS_ENABLED void sentry_metric_count(const char *name, int64_t delta, const char *unit) { if (g_state.enabled && !sentry_metrics_count(&g_state.metrics, name, delta, unit)) { @@ -372,7 +380,9 @@ void sentry_metric_gauge(const char *name, int64_t value, const char *unit) } uint32_t sentry_metrics_dropped_count(void) { return g_state.metrics_dropped; } +#endif /* SENTRY_MICRO_METRICS_ENABLED */ +#if SENTRY_MICRO_LOGS_ENABLED void sentry_log(sentry_level_t level, const char *message, ...) { if (!g_state.enabled || !message) { @@ -463,6 +473,7 @@ static void flush_logs(void) sentry_log_ring_reset(&g_state.log_ring); debug_log("flushed logs: result %d", (int)response.result); } +#endif /* SENTRY_MICRO_LOGS_ENABLED */ /** * Send whatever has accumulated, if anything has. @@ -471,6 +482,7 @@ static void flush_logs(void) * that makes a counter safe in a render loop: recording touches a table, and only the * flush — already on an interval the firmware chose — touches the transport. */ +#if SENTRY_MICRO_METRICS_ENABLED static void flush_metrics(void) { if (sentry_metrics_empty(&g_state.metrics)) { @@ -509,6 +521,7 @@ static void flush_metrics(void) sentry_metrics_reset(&g_state.metrics); debug_log("flushed metrics: result %d", (int)response.result); } +#endif /* SENTRY_MICRO_METRICS_ENABLED */ bool sentry_transaction_start(sentry_transaction_t *txn, const char *name, const char *op) { @@ -678,9 +691,15 @@ uint32_t sentry_flush(uint32_t max_events) } /* Before the buffered envelopes, and outside the buffering check: metrics and logs * accumulate whether or not offline buffering was ever enabled, and a device that never - * buffers still wants its heap reported and its console mirrored. */ + * buffers still wants its heap reported and its console mirrored. Either call compiles + * away entirely when its feature is built out — see SENTRY_MICRO_METRICS_ENABLED / + * SENTRY_MICRO_LOGS_ENABLED. */ +#if SENTRY_MICRO_METRICS_ENABLED flush_metrics(); +#endif +#if SENTRY_MICRO_LOGS_ENABLED flush_logs(); +#endif if (!g_state.buffering) { return 0; diff --git a/src/sentry_micro.h b/src/sentry_micro.h index 0f4a7d9..fe2de2e 100644 --- a/src/sentry_micro.h +++ b/src/sentry_micro.h @@ -412,7 +412,11 @@ sentry_response_t sentry_transaction_finish(sentry_transaction_t *txn); * told the date the table keeps accumulating and nothing is sent — a counter covering a * longer interval is still true, which is why these are held rather than dropped the way a * transaction's stale duration would be. + * + * Not declared when built with `SENTRY_MICRO_METRICS_ENABLED=0` — see that macro in + * `core/sentry_metrics.h`. */ +#if SENTRY_MICRO_METRICS_ENABLED void sentry_metric_count(const char *name, int64_t delta, const char *unit); /** @@ -433,6 +437,7 @@ void sentry_metric_gauge(const char *name, int64_t value, const char *unit); * entirely rather than merely coarse. */ uint32_t sentry_metrics_dropped_count(void); +#endif /* SENTRY_MICRO_METRICS_ENABLED */ /** * Record one console line — a mirror of the serial output for a device with no cable @@ -463,7 +468,11 @@ uint32_t sentry_metrics_dropped_count(void); * * `message` is sent to Sentry like any other log line — do not put a DSN, WiFi password, or * anything else secret into it, the same rule as any logging call. + * + * Not declared when built with `SENTRY_MICRO_LOGS_ENABLED=0` — see that macro in + * `core/sentry_log.h`. */ +#if SENTRY_MICRO_LOGS_ENABLED void sentry_log(sentry_level_t level, const char *message, ...); /** @@ -479,6 +488,7 @@ uint32_t sentry_logs_dropped_count(void); * the line itself for which one, once it reaches Sentry. */ uint32_t sentry_logs_truncated_count(void); +#endif /* SENTRY_MICRO_LOGS_ENABLED */ /** * Report a message — the ordinary, non-crash way to tell Sentry something happened. diff --git a/src/sentry_micro.hpp b/src/sentry_micro.hpp index 1a61af4..8fadf36 100644 --- a/src/sentry_micro.hpp +++ b/src/sentry_micro.hpp @@ -137,6 +137,7 @@ inline sentry_response_t transaction_finish(Transaction &txn) } /** Add to a counter. Does not send; rides the next flush. */ +#if SENTRY_MICRO_METRICS_ENABLED inline void metric_count(const char *name, int64_t delta = 1, const char *unit = nullptr) { sentry_metric_count(name, delta, unit); @@ -150,6 +151,7 @@ inline void metric_gauge(const char *name, int64_t value, const char *unit = nul /** Metric names dropped because the table was full. */ inline uint32_t metrics_dropped() { return sentry_metrics_dropped_count(); } +#endif /* SENTRY_MICRO_METRICS_ENABLED */ /** * Record one console line, printf-style. Does not send; rides the next flush. @@ -159,6 +161,7 @@ inline uint32_t metrics_dropped() { return sentry_metrics_dropped_count(); } * the line itself), so there is nothing left for this wrapper to add by re-deriving that at * compile time. */ +#if SENTRY_MICRO_LOGS_ENABLED template inline void log(sentry_level_t level, const char *message, Args... args) { sentry_log(level, message, args...); @@ -169,6 +172,7 @@ inline uint32_t logs_dropped() { return sentry_logs_dropped_count(); } /** Lines recorded shorter than intended. */ inline uint32_t logs_truncated() { return sentry_logs_truncated_count(); } +#endif /* SENTRY_MICRO_LOGS_ENABLED */ /** Captured messages dropped by the local throttle since init. */ inline uint32_t suppressed_count() { return sentry_suppressed_count(); }