diff --git a/docs/adr/ADR-362-on-node-log-access-is-on-demand.md b/docs/adr/ADR-362-on-node-log-access-is-on-demand.md new file mode 100644 index 000000000..0c3753607 --- /dev/null +++ b/docs/adr/ADR-362-on-node-log-access-is-on-demand.md @@ -0,0 +1,69 @@ +# ADR-362: Reading the on-node log is on-demand, never streamed + +**Status:** Accepted +**Date:** 2026-09-09 +**Follows:** the on-node log engine (persistent 128 B-record ring + coredump-to-flash) + +## Context + +The firmware now keeps a persistent log on the node's `storage` volume and can +write a coredump to flash. Nothing reads either one. The log is a new concept +in this tree, so there is no existing consumer to extend and the access +pattern is genuinely open. + +Two shapes were considered: + +1. **Ingest** — the server polls every node on a schedule, drains new records, + and keeps its own copy that the UI reads. +2. **On-demand** — the server fetches a node's log only when a human asks for + it, and keeps nothing. + +## Decision + +**On-demand only. No streaming, no periodic polling, no server-side copy, no +alerting.** + +The log is pulled after a board hangs or crashes, or while troubleshooting a +specific node. That is the whole access pattern. + +## Why + +- **The persistence already lives on the node.** The ring holds ~208 days at + 128 B per 300 s, and surviving a power cycle is the entire reason the module + exists — a power cycle is how a wedged node gets recovered. A second copy on + the server duplicates a durability property that is already satisfied. +- **Airtime is this fleet's binding constraint, and it is the thing being + diagnosed.** Two nodes uplinking at 1 Mbps were measured consuming 91% of + fleet airtime. A periodic log drain across nine nodes would spend exactly the + resource whose exhaustion is the most common thing you would open the log to + investigate. An instrument must not perturb what it measures. +- **Coredumps are 64 KB.** They are only ever worth moving when something has + actually crashed. +- **The use is diagnostic, not observational.** Nobody watches nine logs. You + open one node's history when that node misbehaves. + +## What this implies gets built + +- A server route that proxies to the node on request — `GET + /api/v1/nodes/{id}/log`, and the same for `/coredump` — authenticating with + the OTA PSK the firmware endpoints already sit behind. +- A page under the existing Tools menu to view one node's records. +- **No** scheduler, **no** new storage, **no** retention policy on the server. + +## Open question, deliberately not settled here + +Whether the server decodes the 128 B records into JSON, or proxies raw bytes +and lets the decoder at the edge (browser, or `node_log_read.py`) interpret +them. + +Decoding server-side means the record layout is defined in two places — C and +Rust — and can drift silently. The pilot already paid for a version of this: +a field whose sentinel the host had to learn to render as `n/a`, where a +plausible wrong value would have been worse than an obvious gap. That argues +for the raw proxy and a single definition of the format. + +## Non-goals + +Real-time monitoring, log streaming, fleet-wide log aggregation, and alerting +on log contents are all explicitly out of scope. If a future need genuinely +requires one of them, it should revisit this ADR rather than grow into it. diff --git a/firmware/esp32-csi-node/main/CMakeLists.txt b/firmware/esp32-csi-node/main/CMakeLists.txt index e70112167..0b342a4ec 100644 --- a/firmware/esp32-csi-node/main/CMakeLists.txt +++ b/firmware/esp32-csi-node/main/CMakeLists.txt @@ -1,5 +1,5 @@ set(SRCS - "main.c" "csi_collector.c" + "main.c" "csi_collector.c" "node_log.c" "thermal.c" "stream_sender.c" "nvs_config.c" "edge_processing.c" "ota_update.c" "power_mgmt.c" "wasm_runtime.c" "wasm_upload.c" "rvf_parser.c" @@ -32,6 +32,9 @@ set(REQUIRES esp_http_client esp_app_format esp_timer + fatfs # node_log.c: the storage FAT volume + wear_levelling # node_log.c: wl_mount behind that volume + espcoredump # coredump-to-flash readback esp_pm esp_driver_uart esp_driver_gpio diff --git a/firmware/esp32-csi-node/main/csi_collector.c b/firmware/esp32-csi-node/main/csi_collector.c index 57c5b49f8..e0666e797 100644 --- a/firmware/esp32-csi-node/main/csi_collector.c +++ b/firmware/esp32-csi-node/main/csi_collector.c @@ -750,6 +750,20 @@ uint16_t csi_collector_get_send_fail_count(void) return (f > 0xFFFFu) ? 0xFFFFu : (uint16_t)f; } +/* The gate here is fixed at compile time (mesh-aligned bucketing, falling + * back to elapsed time when unsynced), so there is no mode or period to + * report. Return the explicit sentinel rather than a number that reads as + * a real setting. */ +uint8_t csi_collector_get_gate_mode(void) +{ + return CSI_GATE_NOT_CONFIGURABLE; +} + +uint8_t csi_collector_get_gate_seq_period(void) +{ + return CSI_GATE_NOT_CONFIGURABLE; +} + /* ---- ADR-029: Channel hopping ---- */ void csi_collector_set_hop_table(const uint8_t *channels, uint8_t hop_count, uint32_t dwell_ms) diff --git a/firmware/esp32-csi-node/main/csi_collector.h b/firmware/esp32-csi-node/main/csi_collector.h index cce99393c..33fb86934 100644 --- a/firmware/esp32-csi-node/main/csi_collector.h +++ b/firmware/esp32-csi-node/main/csi_collector.h @@ -139,4 +139,22 @@ uint16_t csi_collector_get_pkt_yield_per_sec(void); */ uint16_t csi_collector_get_send_fail_count(void); +/** Reported by the gate accessors when this build has no selectable gate. */ +#define CSI_GATE_NOT_CONFIGURABLE 0xFF + +/** + * Report which frame-selection gate is in force, for the on-node log. + * + * This build has exactly one gate -- mesh-aligned bucketing with an + * elapsed-time fallback -- fixed at compile time, so there is no mode or + * period to report and both accessors return CSI_GATE_NOT_CONFIGURABLE. + * + * They exist so the log record keeps a field of fixed width and meaning + * whether or not a build can select a gate at runtime, and so an explicit + * "not applicable" is stored rather than a plausible number that would + * later be reasoned from. + */ +uint8_t csi_collector_get_gate_mode(void); +uint8_t csi_collector_get_gate_seq_period(void); + #endif /* CSI_COLLECTOR_H */ diff --git a/firmware/esp32-csi-node/main/main.c b/firmware/esp32-csi-node/main/main.c index 9431e86f7..035c6efd5 100644 --- a/firmware/esp32-csi-node/main/main.c +++ b/firmware/esp32-csi-node/main/main.c @@ -21,6 +21,7 @@ #include "led_strip.h" #include "csi_collector.h" +#include "node_log.h" #include "thermal.h" #include "stream_sender.h" #include "nvs_config.h" @@ -116,6 +117,10 @@ static void event_handler(void *arg, esp_event_base_t event_base, } else if (event_base == WIFI_EVENT && event_id == WIFI_EVENT_STA_DISCONNECTED) { wifi_event_sta_disconnected_t *disc = (wifi_event_sta_disconnected_t *)event_data; ESP_LOGW(TAG, "WiFi disconnected, reason=%d rssi=%d", disc->reason, disc->rssi); + /* The 7.5 h outage was root-caused to the MAX_RETRY latch only because + * someone was watching the console at the time. Persist it. */ + node_log_note_disconnect((uint8_t)disc->reason, (int8_t)disc->rssi); + node_log_event(NODE_LOG_EV_WIFI_DISCONNECT, disc->reason, disc->rssi); s_retry_num++; /* Release the boot wait once, so a node that comes up while the AP is * down still starts CSI capture and the mesh instead of blocking in @@ -451,6 +456,24 @@ void app_main(void) } else { ESP_LOGI(TAG, "reset reason: %s (%d)", why, (int)rr); } + + /* And persist it. The console line above is exactly what a power cycle + * destroys, which is the whole reason this fleet has no post-mortem for + * a remote fault. node_log_init failing is non-fatal by design -- the + * node comes up either way, it just has no memory. */ + if (node_log_init() == ESP_OK) { + uint32_t prev_uptime_s = 0; + nvs_handle_t nh; + if (nvs_open("nodelog", NVS_READWRITE, &nh) == ESP_OK) { + nvs_get_u32(nh, "last_up_s", &prev_uptime_s); + nvs_set_u32(nh, "last_up_s", 0); + nvs_commit(nh); + nvs_close(nh); + } + node_log_boot((uint32_t)rr, prev_uptime_s); + ESP_LOGI(TAG, "on-node log active: boot_id=%u, %u records retained", + (unsigned)node_log_boot_id(), (unsigned)node_log_count()); + } } /* Bring thermal monitoring up before the radio is loaded, so the first @@ -655,5 +678,24 @@ void app_main(void) #ifdef CONFIG_UPLINK_WATCHDOG uplink_watchdog_tick(); #endif + /* Offered every 10 s; node_log enforces its own floor, so the cadence + * lives in one place rather than being implied by this loop's delay. + * Also refresh the uptime NVS cell, which is what lets the NEXT boot + * record say how long the previous session actually survived -- the + * difference between "it rebooted" and "it wedged after 225 s". */ + node_log_periodic(); + { + static uint32_t s_last_persist_s; + uint32_t up_s = (uint32_t)(esp_timer_get_time() / 1000000); + if (up_s - s_last_persist_s >= 60) { + s_last_persist_s = up_s; + nvs_handle_t nh; + if (nvs_open("nodelog", NVS_READWRITE, &nh) == ESP_OK) { + nvs_set_u32(nh, "last_up_s", up_s); + nvs_commit(nh); + nvs_close(nh); + } + } + } } } diff --git a/firmware/esp32-csi-node/main/node_log.c b/firmware/esp32-csi-node/main/node_log.c new file mode 100644 index 000000000..741b4bd72 --- /dev/null +++ b/firmware/esp32-csi-node/main/node_log.c @@ -0,0 +1,382 @@ +#include "node_log.h" + +#include +#include +#include + +#include "esp_log.h" +#include "esp_system.h" +#include "esp_timer.h" +#include "esp_vfs_fat.h" +#include "esp_wifi.h" +#include "freertos/FreeRTOS.h" +#include "freertos/semphr.h" +#include "nvs.h" +#include "nvs_flash.h" + +#include "c6_sync_espnow.h" +#include "csi_collector.h" +#include "nvs_config.h" +#include "thermal.h" + +static const char *TAG = "node_log"; + +/* The FAT volume reserved in partitions_16mb.csv (storage, 8000K) and never + * mounted until now. */ +#define NODE_LOG_PARTITION "storage" +#define NODE_LOG_MOUNT "/nlog" +#define NODE_LOG_PATH NODE_LOG_MOUNT "/health.bin" + +/* Ring capacity. 60000 * 128 B = 7.68 MB, just inside the 8000K volume with + * room for FAT's own metadata. At the 300 s cadence that is ~208 days. */ +#define NODE_LOG_MAX_RECORDS 60000 + +/* Hard floor between periodic samples. The design settled on 300 s; this is + * the enforcement, not the schedule. A caller asking more often is DROPPED + * rather than served, because flash wear is the one way this module can do + * harm and a bug in a caller must not be able to cause it. */ +#define NODE_LOG_MIN_PERIOD_S 60 + +/* Events bypass the periodic floor -- they are rare and they are the whole + * point -- but not without limit, or a disconnect storm becomes a write storm. */ +#define NODE_LOG_MIN_EVENT_MS 1000 + +static bool s_active; +static FILE *s_fp; +static wl_handle_t s_wl = WL_INVALID_HANDLE; +static SemaphoreHandle_t s_lock; +static uint16_t s_boot_id; +static uint32_t s_seq; +static size_t s_count; /* records currently in the ring */ +static size_t s_head; /* next slot to write */ +static int64_t s_last_periodic_us; +static int64_t s_last_event_us; + +/* CRC16/CCITT-FALSE. A record that fails this is skipped by the reader rather + * than trusted, which matters because a power cut mid-write leaves a partial + * record and the ring has no other way to know. */ +static uint16_t crc16(const uint8_t *p, size_t n) +{ + uint16_t crc = 0xFFFF; + for (size_t i = 0; i < n; i++) { + crc ^= (uint16_t)p[i] << 8; + for (int b = 0; b < 8; b++) { + crc = (crc & 0x8000) ? (uint16_t)((crc << 1) ^ 0x1021) : (uint16_t)(crc << 1); + } + } + return crc; +} + +/* 16 B header, then a type-specific payload. The header is identical across + * types so a reader can order and validate without dispatching first. */ +typedef struct __attribute__((packed)) { + uint8_t type; + uint8_t flags; + uint16_t boot_id; + uint32_t seq; + uint32_t uptime_s; + uint16_t payload_len; + uint16_t crc16; /* over the record with this field zeroed */ +} node_log_hdr_t; + +_Static_assert(sizeof(node_log_hdr_t) == 16, "header must be 16 B"); + +/* ~72 B used of the 112 B payload budget, leaving ~40 B of deliberate slack so + * a field can be added later WITHOUT changing the record size and invalidating + * every reader already in the field. */ +typedef struct __attribute__((packed)) { + int8_t die_c; + uint8_t thermal_state; + int8_t tx_dbm; + int8_t ap_rssi_dbm; /* the one field we did not have and needed */ + uint8_t channel; + uint8_t wifi_state; + uint8_t gate_mode; + uint8_t gate_seq_period; + uint16_t free_heap_kib; + uint16_t min_heap_kib; + uint16_t csi_fps_x100; + uint32_t frames_processed; + uint32_t frames_rejected; + uint32_t seq_drop; + uint32_t tx_early_drop; + uint16_t tx_rate_skip; + uint32_t tx_send_fail; + uint16_t disconnect_count; + uint8_t last_disc_reason; + int8_t last_disc_rssi; + uint8_t mesh_flags; /* bit0 valid, bit1 leader */ + uint8_t leader_id; + int32_t mesh_offset_us; + uint16_t mesh_staleness_ms; + uint32_t mesh_seq; +} node_log_periodic_t; + +typedef struct __attribute__((packed)) { + uint32_t reset_reason; + uint32_t prev_uptime_s; + node_log_periodic_t health; /* a boot record carries a snapshot too */ +} node_log_boot_t; + +typedef struct __attribute__((packed)) { + uint8_t subtype; + uint8_t _pad[3]; + int32_t a; + int32_t b; +} node_log_event_t; + +/* Counters main.c owns; set through the setters below rather than reached for, + * so this module has no include cycle with main.c. */ +static volatile uint16_t s_disconnect_count; +static volatile uint8_t s_last_disc_reason; +static volatile int8_t s_last_disc_rssi; + +void node_log_note_disconnect(uint8_t reason, int8_t rssi) +{ + s_disconnect_count++; + s_last_disc_reason = reason; + s_last_disc_rssi = rssi; +} + +static void fill_health(node_log_periodic_t *h) +{ + memset(h, 0, sizeof(*h)); + + /* thermal.c initialises s_last_c to -273.0f and only replaces it on the + * first thermal_tick(), which runs from the adaptive controller -- LATER + * than the boot record and later than the first periodic samples. Casting + * that sentinel to int8 yields -17, a PLAUSIBLE temperature, which is + * exactly the kind of invented-but-believable number that must never reach + * a log someone will later reason from. Store INT8_MIN as an explicit + * "no reading" instead; node_log_read.py renders it as n/a. */ + float die = thermal_celsius(); + h->die_c = (die < -100.0f || die > 125.0f) ? INT8_MIN : (int8_t)die; + h->thermal_state = (uint8_t)thermal_state(); + h->tx_dbm = thermal_tx_dbm(); + h->gate_mode = csi_collector_get_gate_mode(); + h->gate_seq_period = csi_collector_get_gate_seq_period(); + + /* The association link, NOT the CSI-derived rssi_median_dbm in + * adaptive_controller.c. Nodes 5 and 6 show every symptom of a bad uplink + * and this is the one call that can confirm or refute it. */ + wifi_ap_record_t ap; + if (esp_wifi_sta_get_ap_info(&ap) == ESP_OK) { + h->ap_rssi_dbm = (int8_t)ap.rssi; + h->channel = ap.primary; + h->wifi_state = 1; + } + + h->free_heap_kib = (uint16_t)(esp_get_free_heap_size() / 1024); + h->min_heap_kib = (uint16_t)(esp_get_minimum_free_heap_size() / 1024); + h->csi_fps_x100 = csi_collector_get_pkt_yield_per_sec() * 100; + h->tx_send_fail = csi_collector_get_send_fail_count(); + + h->disconnect_count = s_disconnect_count; + h->last_disc_reason = s_last_disc_reason; + h->last_disc_rssi = s_last_disc_rssi; + + h->mesh_flags = (uint8_t)((c6_sync_espnow_is_valid() ? 1 : 0) + | (c6_sync_espnow_is_leader() ? 2 : 0)); + int64_t off = c6_sync_espnow_get_offset_us(); + /* Saturate rather than wrap: a wrapped offset reads as a plausible small + * number and would be believed. */ + if (off > INT32_MAX) h->mesh_offset_us = INT32_MAX; + else if (off < INT32_MIN) h->mesh_offset_us = INT32_MIN; + else h->mesh_offset_us = (int32_t)off; +} + +/* Append one record. Callers hold no lock; this takes it. */ +static void append(uint8_t type, const void *payload, size_t len) +{ + if (!s_active || len > (NODE_LOG_RECORD_SIZE - sizeof(node_log_hdr_t))) { + return; + } + if (xSemaphoreTake(s_lock, pdMS_TO_TICKS(200)) != pdTRUE) { + return; /* never block a caller on the log */ + } + + uint8_t rec[NODE_LOG_RECORD_SIZE]; + memset(rec, 0, sizeof(rec)); + node_log_hdr_t *h = (node_log_hdr_t *)rec; + h->type = type; + h->boot_id = s_boot_id; + h->seq = ++s_seq; + h->uptime_s = (uint32_t)(esp_timer_get_time() / 1000000); + h->payload_len = (uint16_t)len; + h->crc16 = 0; + memcpy(rec + sizeof(*h), payload, len); + h->crc16 = crc16(rec, sizeof(rec)); + + if (fseek(s_fp, (long)(s_head * NODE_LOG_RECORD_SIZE), SEEK_SET) == 0 + && fwrite(rec, 1, sizeof(rec), s_fp) == sizeof(rec)) { + /* fflush only pushes the C stdio buffer into the VFS; FATFS still holds + * the directory entry and FAT chain in RAM. Without fsync a reboot + * loses the file's size, and on the next open "r+b" sees a zero-length + * file -- which is precisely what the node-3 pilot showed: boot 1's + * records vanished while the NVS-backed prev_uptime survived. A log + * that does not survive a power cycle is the exact thing this module + * exists to prevent, so the cost of an fsync per record is accepted: + * at one record per 60 s it is nothing, and the bounded write rate is + * what keeps it that way. */ + fflush(s_fp); + fsync(fileno(s_fp)); + s_head = (s_head + 1) % NODE_LOG_MAX_RECORDS; + if (s_count < NODE_LOG_MAX_RECORDS) s_count++; + } else { + ESP_LOGW(TAG, "record write failed; disabling to protect the volume"); + s_active = false; + } + xSemaphoreGive(s_lock); +} + +esp_err_t node_log_init(void) +{ + if (s_active) return ESP_OK; + + s_lock = xSemaphoreCreateMutex(); + if (!s_lock) return ESP_ERR_NO_MEM; + + const esp_vfs_fat_mount_config_t cfg = { + .format_if_mount_failed = true, + .max_files = 2, + .allocation_unit_size = CONFIG_WL_SECTOR_SIZE, + }; + esp_err_t err = esp_vfs_fat_spiflash_mount_rw_wl( + NODE_LOG_MOUNT, NODE_LOG_PARTITION, &cfg, &s_wl); + if (err != ESP_OK) { + ESP_LOGW(TAG, "FAT mount failed (%s); logging DISABLED, node unaffected", + esp_err_to_name(err)); + return err; + } + + /* boot_id orders records across reboots. Without an RTC it is the only + * ordering that survives a power cycle. */ + nvs_handle_t nh; + if (nvs_open("nodelog", NVS_READWRITE, &nh) == ESP_OK) { + uint16_t b = 0; + nvs_get_u16(nh, "boot_id", &b); + s_boot_id = (uint16_t)(b + 1); + nvs_set_u16(nh, "boot_id", s_boot_id); + nvs_commit(nh); + nvs_close(nh); + } + + s_fp = fopen(NODE_LOG_PATH, "r+b"); + if (!s_fp) { + /* First boot only. Create it, then fsync so the directory entry is on + * flash before anything is written into it. */ + s_fp = fopen(NODE_LOG_PATH, "w+b"); + if (s_fp) { + fflush(s_fp); + fsync(fileno(s_fp)); + } + } + if (!s_fp) { + ESP_LOGW(TAG, "cannot open %s; logging DISABLED", NODE_LOG_PATH); + esp_vfs_fat_spiflash_unmount_rw_wl(NODE_LOG_MOUNT, s_wl); + s_wl = WL_INVALID_HANDLE; + return ESP_FAIL; + } + + /* Recover head/seq by scanning. The ring has no superblock deliberately: + * a superblock is one more thing a power cut can leave inconsistent, and + * the scan is a one-off cost at boot. */ + uint8_t rec[NODE_LOG_RECORD_SIZE]; + uint32_t best_seq = 0; + for (size_t i = 0; i < NODE_LOG_MAX_RECORDS; i++) { + if (fseek(s_fp, (long)(i * NODE_LOG_RECORD_SIZE), SEEK_SET) != 0) break; + if (fread(rec, 1, sizeof(rec), s_fp) != sizeof(rec)) break; + node_log_hdr_t *h = (node_log_hdr_t *)rec; + if (h->type == 0) continue; + uint16_t got = h->crc16; + h->crc16 = 0; + if (crc16(rec, sizeof(rec)) != got) continue; + s_count++; + if (h->seq > best_seq) { + best_seq = h->seq; + s_head = (i + 1) % NODE_LOG_MAX_RECORDS; + } + } + s_seq = best_seq; + s_active = true; + ESP_LOGI(TAG, "logging active: boot_id=%u recovered=%u records, head=%u", + (unsigned)s_boot_id, (unsigned)s_count, (unsigned)s_head); + return ESP_OK; +} + +bool node_log_is_active(void) { return s_active; } +uint16_t node_log_boot_id(void) { return s_boot_id; } +size_t node_log_count(void) { return s_count; } + +void node_log_boot(uint32_t reset_reason, uint32_t prev_uptime_s) +{ + node_log_boot_t b; + memset(&b, 0, sizeof(b)); + b.reset_reason = reset_reason; + b.prev_uptime_s = prev_uptime_s; + fill_health(&b.health); + append(NODE_LOG_TYPE_BOOT, &b, sizeof(b)); +} + +void node_log_periodic(void) +{ + int64_t now = esp_timer_get_time(); + if (s_last_periodic_us != 0 + && (now - s_last_periodic_us) < (int64_t)NODE_LOG_MIN_PERIOD_S * 1000000) { + return; + } + s_last_periodic_us = now; + node_log_periodic_t h; + fill_health(&h); + append(NODE_LOG_TYPE_PERIODIC, &h, sizeof(h)); +} + +void node_log_event(uint8_t subtype, int32_t a, int32_t b) +{ + int64_t now = esp_timer_get_time(); + if (s_last_event_us != 0 + && (now - s_last_event_us) < (int64_t)NODE_LOG_MIN_EVENT_MS * 1000) { + return; + } + s_last_event_us = now; + node_log_event_t e; + memset(&e, 0, sizeof(e)); + e.subtype = subtype; + e.a = a; + e.b = b; + append(NODE_LOG_TYPE_EVENT, &e, sizeof(e)); +} + +size_t node_log_read(uint8_t *out, size_t max_records, size_t skip) +{ + if (!s_active || !out || max_records == 0) return 0; + if (xSemaphoreTake(s_lock, pdMS_TO_TICKS(500)) != pdTRUE) return 0; + + size_t written = 0; + for (size_t n = 0; n < s_count && written < max_records; n++) { + if (n < skip) continue; + /* newest-first: step back from head */ + size_t idx = (s_head + NODE_LOG_MAX_RECORDS - 1 - n) % NODE_LOG_MAX_RECORDS; + if (fseek(s_fp, (long)(idx * NODE_LOG_RECORD_SIZE), SEEK_SET) != 0) break; + if (fread(out + written * NODE_LOG_RECORD_SIZE, 1, NODE_LOG_RECORD_SIZE, s_fp) + != NODE_LOG_RECORD_SIZE) break; + written++; + } + xSemaphoreGive(s_lock); + return written; +} + +esp_err_t node_log_clear(void) +{ + if (!s_active) return ESP_ERR_INVALID_STATE; + if (xSemaphoreTake(s_lock, pdMS_TO_TICKS(1000)) != pdTRUE) return ESP_ERR_TIMEOUT; + esp_err_t err = ESP_OK; + if (s_fp) { fclose(s_fp); s_fp = NULL; } + s_fp = fopen(NODE_LOG_PATH, "w+b"); + if (!s_fp) { s_active = false; err = ESP_FAIL; } + s_count = 0; + s_head = 0; + s_seq = 0; + xSemaphoreGive(s_lock); + return err; +} diff --git a/firmware/esp32-csi-node/main/node_log.h b/firmware/esp32-csi-node/main/node_log.h new file mode 100644 index 000000000..ee1988a9a --- /dev/null +++ b/firmware/esp32-csi-node/main/node_log.h @@ -0,0 +1,114 @@ +/* Persistent on-node log -- survives a power cycle, readable without a cable. + * + * The problem this exists for (Joe, 2026-09-07): "a hung node ... doesnt do us + * any good for troubleshooting remotly because the unplug and mount results in + * a clearing of the condtion." Today the post-mortem for any remote fault is + * nothing: main.c decodes the reset reason at boot and logs it to the CONSOLE, + * which is exactly what a power cycle destroys. + * + * The flash was already partitioned for this and the features were off -- + * partitions_16mb.csv reserves a 64K coredump partition and an 8000K storage + * FAT volume, neither of which had ever been mounted or written. + * + * # Retention, not wear, is the binding constraint + * + * 128 B records every 300 s fills 8 MB in ~222 days. Endurance at that rate is + * ~61,000 years, so the ring wraps 36 million times before the flash is at + * risk. The write rate is nonetheless bounded explicitly below, because flash + * wear is the one way this module can do harm. + * + * # Why uptime and boot_id rather than a timestamp + * + * These boards have no RTC. Nothing can be timestamped absolutely, so ordering + * comes from boot_id (incremented once per boot, persisted in NVS) plus + * uptime_s within that boot. That ordering survives a power cycle; a wall clock + * would not. + * + * # Counters are stored RAW + * + * Every counter here is cumulative and is written as-is. Differencing happens + * at read time. Storing rates instead would bake in the sampling interval and + * make every record useless the moment the cadence changed. + */ +#pragma once + +#include +#include +#include + +#include "esp_err.h" + +#ifdef __cplusplus +extern "C" { +#endif + +/** Every record is exactly this size, so the ring is index-addressable and a + * reader never has to parse forward to find a boundary. */ +#define NODE_LOG_RECORD_SIZE 128 + +/** Record types. A reader dispatches on this byte alone. */ +#define NODE_LOG_TYPE_PERIODIC 1 +#define NODE_LOG_TYPE_BOOT 2 +#define NODE_LOG_TYPE_EVENT 3 + +/** Event subtypes. Periodic samples give the trend; these give the moment. */ +#define NODE_LOG_EV_WIFI_DISCONNECT 1 +#define NODE_LOG_EV_WIFI_RECONNECT 2 +#define NODE_LOG_EV_THERMAL_STATE 3 +#define NODE_LOG_EV_SEND_FAIL_RATE 4 +#define NODE_LOG_EV_WATCHDOG 5 + +/** Mount the FAT volume and open the ring. Call once at boot, after NVS is up + * (the boot counter lives there). + * + * Failure is NOT fatal: on any error this module disables itself and every + * other entry point becomes a no-op. A logging volume that will not mount must + * never take the fleet down with it. */ +esp_err_t node_log_init(void); + +/** True when the ring mounted and writes are being accepted. */ +bool node_log_is_active(void); + +/** Append the boot record: reset reason, the previous session's final uptime, + * and a health snapshot. + * + * The highest-value record here. It catches a HANG FOLLOWED BY A WATCHDOG + * RESET, which is the failure that bites this fleet and the one a coredump + * does not capture. */ +void node_log_boot(uint32_t reset_reason, uint32_t prev_uptime_s); + +/** Append a periodic health sample. Rate-limited internally, so a caller cannot + * wear the flash by calling it in a tight loop. */ +void node_log_periodic(void); + +/** Append an event record. a/b carry subtype-specific detail -- for a WiFi + * disconnect they are the reason code and the RSSI at that moment, the pair + * main.c currently logs only to the console. */ +void node_log_event(uint8_t subtype, int32_t a, int32_t b); + +/** Record a WiFi disconnect for the health snapshot's cumulative counters. + * Kept as a setter so this module has no include cycle with main.c, which is + * where the reason and RSSI are actually known. */ +void node_log_note_disconnect(uint8_t reason, int8_t rssi); + +/** Copy raw records into out, newest-first, for the HTTP reader. + * + * @param out destination, at least max_records * NODE_LOG_RECORD_SIZE + * @param max_records maximum to copy + * @param skip how many of the newest to skip, so a caller can page + * @return number of records written into out */ +size_t node_log_read(uint8_t *out, size_t max_records, size_t skip); + +/** Total records currently held in the ring. */ +size_t node_log_count(void); + +/** Boot id of the current session. Records from the same boot share it. */ +uint16_t node_log_boot_id(void); + +/** Erase every record. Deliberately explicit and never called automatically -- + * the whole point of the module is that state survives. */ +esp_err_t node_log_clear(void); + +#ifdef __cplusplus +} +#endif diff --git a/firmware/esp32-csi-node/sdkconfig.defaults.16mb b/firmware/esp32-csi-node/sdkconfig.defaults.16mb index f36c59282..124146e42 100644 --- a/firmware/esp32-csi-node/sdkconfig.defaults.16mb +++ b/firmware/esp32-csi-node/sdkconfig.defaults.16mb @@ -21,3 +21,21 @@ CONFIG_PARTITION_TABLE_CUSTOM_FILENAME="partitions_16mb.csv" # itself, or the bootloader reverts on the next boot. See ota_rollback_* in # ota_update.c for when confirmation happens and why. CONFIG_BOOTLOADER_APP_ROLLBACK_ENABLE=y + +# Coredump to flash. The 64K `coredump` partition has existed in +# partitions_16mb.csv since the 16MB layout was written and has never held +# anything, because the build defaulted to +# CONFIG_ESP_COREDUMP_ENABLE_TO_NONE=y. A panic therefore left no stack trace +# on a fleet whose faults are all remote. +# +# Complementary to the on-node log, not a substitute: a coredump captures a +# CRASH, and the log's boot record captures a HANG followed by a watchdog +# reset -- which is the failure this fleet actually sees. +CONFIG_ESP_COREDUMP_ENABLE_TO_FLASH=y +CONFIG_ESP_COREDUMP_DATA_FORMAT_ELF=y +CONFIG_ESP_COREDUMP_CHECKSUM_CRC32=y +CONFIG_ESP_COREDUMP_LOGS=y + +# The `storage` FAT volume (8000K) that node_log.c mounts. Reserved in the +# same partition table and likewise never used until now. +CONFIG_WL_SECTOR_SIZE_4096=y