diff --git a/CHANGELOG.md b/CHANGELOG.md index f664a9b..22673e3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -276,3 +276,53 @@ 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. +- `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 179e15f..00205cf 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. @@ -747,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 | | | @@ -776,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/examples/wifi_basic/src/main.cpp b/examples/wifi_basic/src/main.cpp index 6d45801..b7ec171 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; } @@ -449,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); @@ -479,12 +502,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", @@ -492,6 +523,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 @@ -519,23 +555,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()) { @@ -551,6 +608,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(); } @@ -575,14 +648,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); } 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")); } 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..67c5ff1 --- /dev/null +++ b/src/core/sentry_log.c @@ -0,0 +1,218 @@ +#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, bool truncated) +{ + 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; + /* 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; +} + +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)); + + /* + * 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); + 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); + 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..2e882b5 --- /dev/null +++ b/src/core/sentry_log.h @@ -0,0 +1,142 @@ +/** + * 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 */ + +/** + * 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 + +/** + * 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 6 +#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; + /** Whether `body` is shorter than what was actually meant to be logged. */ + bool truncated; + 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. + * + * `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, 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); + +/** + * 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/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 afd844d..f2767e1 100644 --- a/src/sentry_micro.c +++ b/src/sentry_micro.c @@ -42,10 +42,30 @@ 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. 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. + * + * 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; + /** 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. @@ -344,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)) { @@ -359,6 +380,100 @@ 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) { + return; + } + char body[SENTRY_MICRO_LOG_BODY_LEN]; + va_list args; + va_start(args, message); + /* 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, + 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. + * + * 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); +} +#endif /* SENTRY_MICRO_LOGS_ENABLED */ /** * Send whatever has accumulated, if anything has. @@ -367,6 +482,7 @@ uint32_t sentry_metrics_dropped_count(void) { return g_state.metrics_dropped; } * 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)) { @@ -405,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) { @@ -572,10 +689,17 @@ 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. 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 25a96fd..fe2de2e 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" @@ -411,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); /** @@ -432,6 +437,58 @@ 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 + * 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. 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 + * 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. + * + * 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, ...); + +/** + * 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); + +/** + * 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); +#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 3fc86d7..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,28 @@ 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. + * + * 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. + */ +#if SENTRY_MICRO_LOGS_ENABLED +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(); } +#endif /* SENTRY_MICRO_LOGS_ENABLED */ /** 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 new file mode 100644 index 0000000..a341451 --- /dev/null +++ b/test/test_log/test_log.c @@ -0,0 +1,451 @@ +/** + * 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", 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); + 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", false); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, TRACE, 2000, "tick", false); + 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, false)); + } + TEST_ASSERT_EQUAL_UINT(SENTRY_MICRO_MAX_LOGS, r.count); + TEST_ASSERT_EQUAL_UINT(0, r.dropped); + + /* 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); + + 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]; + 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, false); + } + /* 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, + (uint64_t)(SENTRY_MICRO_MAX_LOGS + 1) * 1000, NOW_UNIX_US); + TEST_ASSERT_TRUE(len > 0 && len < sizeof(buf)); + + /* 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) +{ + 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'; + /* 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", false); + + 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", false); + + 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", false); + sentry_log_ring_push(&r, SENTRY_LEVEL_INFO, "", 2000, "after it ended", false); + + 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", false); + + 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 "\"")); + /* 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. */ + 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", false); + 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", false); + 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", false); + + /* 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", false); + + 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", 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. */ + 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", false); + + 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_it_not_the_attributes(void) +{ + sentry_log_ring_t r; + char buf[2048]; + sentry_log_ring_reset(&r); + /* 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); + TEST_ASSERT_TRUE(len > 0); + 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", 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, false)); + 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_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); + 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_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(); +}