feat: add HIL diagnostics and meter health handling
This commit is contained in:
+221
-37
@@ -6,6 +6,7 @@
|
||||
#include "compressor.h"
|
||||
#include "lora_transport.h"
|
||||
#include "meter_driver.h"
|
||||
#include "meter_health.h"
|
||||
#include "power_manager.h"
|
||||
#include "time_manager.h"
|
||||
#include "wifi_manager.h"
|
||||
@@ -14,11 +15,15 @@
|
||||
#include "display_ui.h"
|
||||
#include "test_mode.h"
|
||||
#include "sd_logger.h"
|
||||
#include "hil_trace.h"
|
||||
#include <stdarg.h>
|
||||
#include <math.h>
|
||||
#ifdef ARDUINO_ARCH_ESP32
|
||||
#include <esp_task_wdt.h>
|
||||
#include <esp_system.h>
|
||||
#include <freertos/FreeRTOS.h>
|
||||
#include <freertos/queue.h>
|
||||
#include <freertos/task.h>
|
||||
#endif
|
||||
|
||||
static DeviceRole g_role = DeviceRole::Sender;
|
||||
@@ -111,6 +116,17 @@ static MeterData g_last_meter_data = {};
|
||||
static bool g_last_meter_valid = false;
|
||||
static uint32_t g_last_meter_rx_ms = 0;
|
||||
static uint32_t g_meter_stale_seconds = 0;
|
||||
static MeterHealthState g_meter_health_state = {};
|
||||
static constexpr uint32_t METER_SAMPLE_MAX_AGE_MS = 15000;
|
||||
#ifdef ARDUINO_ARCH_ESP32
|
||||
struct MeterSampleEvent {
|
||||
MeterData data;
|
||||
uint32_t rx_ms;
|
||||
};
|
||||
static QueueHandle_t g_meter_sample_queue = nullptr;
|
||||
static TaskHandle_t g_meter_reader_task = nullptr;
|
||||
static bool g_meter_reader_task_running = false;
|
||||
#endif
|
||||
static constexpr uint32_t SENDER_TIMESYNC_ACQUIRE_MS = 10UL * 60UL * 1000UL;
|
||||
static constexpr uint32_t SENDER_TIMESYNC_ACQUIRE_INTERVAL_SEC = 20;
|
||||
static constexpr uint32_t SENDER_TIMESYNC_ACQUIRE_WINDOW_MS = 3000;
|
||||
@@ -126,7 +142,73 @@ static void serial_debug_printf(const char *fmt, ...) {
|
||||
va_start(args, fmt);
|
||||
vsnprintf(buf, sizeof(buf), fmt, args);
|
||||
va_end(args);
|
||||
Serial.println(buf);
|
||||
Serial.printf("%s\n", buf);
|
||||
}
|
||||
|
||||
static void set_last_meter_sample(const MeterData &parsed, uint32_t rx_ms) {
|
||||
g_last_meter_data = parsed;
|
||||
g_last_meter_valid = true;
|
||||
g_last_meter_rx_ms = rx_ms;
|
||||
g_meter_stale_seconds = 0;
|
||||
}
|
||||
|
||||
static bool poll_and_parse_meter(MeterData &parsed) {
|
||||
const char *frame = nullptr;
|
||||
size_t frame_len = 0;
|
||||
if (!meter_poll_frame(frame, frame_len)) return false;
|
||||
parsed = {};
|
||||
parsed.energy_total_kwh = NAN;
|
||||
parsed.total_power_w = NAN;
|
||||
parsed.phase_power_w[0] = NAN;
|
||||
parsed.phase_power_w[1] = NAN;
|
||||
parsed.phase_power_w[2] = NAN;
|
||||
parsed.valid = false;
|
||||
return meter_parse_frame(frame, frame_len, parsed);
|
||||
}
|
||||
|
||||
#ifdef ARDUINO_ARCH_ESP32
|
||||
static void meter_reader_task_entry(void *) {
|
||||
for (;;) {
|
||||
MeterData parsed = {};
|
||||
if (!poll_and_parse_meter(parsed)) {
|
||||
vTaskDelay(pdMS_TO_TICKS(5));
|
||||
continue;
|
||||
}
|
||||
MeterSampleEvent event = {};
|
||||
event.data = parsed;
|
||||
event.rx_ms = millis();
|
||||
xQueueOverwrite(g_meter_sample_queue, &event);
|
||||
}
|
||||
}
|
||||
|
||||
static bool meter_reader_start() {
|
||||
g_meter_sample_queue = xQueueCreate(1, sizeof(MeterSampleEvent));
|
||||
if (!g_meter_sample_queue) return false;
|
||||
BaseType_t rc = xTaskCreatePinnedToCore(meter_reader_task_entry, "meter_reader", 4096,
|
||||
nullptr, 2, &g_meter_reader_task, 0);
|
||||
if (rc != pdPASS) {
|
||||
vQueueDelete(g_meter_sample_queue);
|
||||
g_meter_sample_queue = nullptr;
|
||||
return false;
|
||||
}
|
||||
g_meter_reader_task_running = true;
|
||||
serial_debug_printf("meter: reader task started rx_buffer=8192");
|
||||
return true;
|
||||
}
|
||||
#endif
|
||||
|
||||
static void meter_reader_pump(uint32_t now_ms) {
|
||||
#ifdef ARDUINO_ARCH_ESP32
|
||||
if (g_meter_reader_task_running && g_meter_sample_queue) {
|
||||
MeterSampleEvent event = {};
|
||||
if (xQueueReceive(g_meter_sample_queue, &event, 0) == pdTRUE) {
|
||||
set_last_meter_sample(event.data, event.rx_ms);
|
||||
}
|
||||
return;
|
||||
}
|
||||
#endif
|
||||
MeterData parsed = {};
|
||||
if (poll_and_parse_meter(parsed)) set_last_meter_sample(parsed, now_ms);
|
||||
}
|
||||
|
||||
static void sender_set_timesync_mode(uint8_t mode) {
|
||||
@@ -216,7 +298,7 @@ static bool sender_timesync_window_due() {
|
||||
return false;
|
||||
}
|
||||
|
||||
static bool batch_queue_drop_oldest() {
|
||||
static bool batch_queue_remove_oldest(bool overflow_drop) {
|
||||
if (g_batch_count == 0) {
|
||||
return false;
|
||||
}
|
||||
@@ -231,6 +313,12 @@ static bool batch_queue_drop_oldest() {
|
||||
}
|
||||
g_batch_tail = (g_batch_tail + 1) % BATCH_QUEUE_DEPTH;
|
||||
g_batch_count--;
|
||||
if (overflow_drop) {
|
||||
hil_trace_eventf("queue_drop", "\"queue\":%u,\"inflight\":%s", g_batch_count,
|
||||
dropped_inflight ? "true" : "false");
|
||||
} else {
|
||||
hil_trace_eventf("queue", "\"action\":\"dequeue_acked\",\"queue\":%u", g_batch_count);
|
||||
}
|
||||
return dropped_inflight;
|
||||
}
|
||||
|
||||
@@ -279,7 +367,7 @@ static void batch_queue_enqueue(const MeterData *samples, uint8_t count) {
|
||||
return;
|
||||
}
|
||||
if (g_batch_count >= BATCH_QUEUE_DEPTH) {
|
||||
if (batch_queue_drop_oldest()) {
|
||||
if (batch_queue_remove_oldest(true)) {
|
||||
g_batch_id++;
|
||||
}
|
||||
}
|
||||
@@ -292,6 +380,8 @@ static void batch_queue_enqueue(const MeterData *samples, uint8_t count) {
|
||||
}
|
||||
g_batch_head = (g_batch_head + 1) % BATCH_QUEUE_DEPTH;
|
||||
g_batch_count++;
|
||||
hil_trace_eventf("queue", "\"action\":\"enqueue\",\"queue\":%u,\"samples\":%u",
|
||||
g_batch_count, count);
|
||||
}
|
||||
|
||||
static uint32_t last_sample_ts() {
|
||||
@@ -482,8 +572,23 @@ static bool send_batch_payload(const uint8_t *data, size_t len, uint32_t ts_for_
|
||||
|
||||
watchdog_kick();
|
||||
uint32_t tx_start = millis();
|
||||
bool ok = lora_send(pkt);
|
||||
bool dropped = hil_fault_take(HilFault::DropChunk);
|
||||
bool duplicate = false;
|
||||
bool ok = dropped ? true : lora_send(pkt);
|
||||
if (!dropped && hil_fault_take(HilFault::DuplicateChunk)) {
|
||||
duplicate = true;
|
||||
delay(10);
|
||||
ok = lora_send(pkt) && ok;
|
||||
}
|
||||
uint32_t tx_ms = millis() - tx_start;
|
||||
hil_trace_eventf("chunk_tx", "\"batch_id\":%u,\"index\":%u,\"count\":%u,\"len\":%u,\"crc32\":%lu,\"ok\":%s,\"dropped\":%s,\"duplicate\":%s",
|
||||
batch_id, i, chunk_count, static_cast<unsigned>(chunk_len),
|
||||
static_cast<unsigned long>(hil_crc32(data + offset, chunk_len)), ok ? "true" : "false",
|
||||
dropped ? "true" : "false", duplicate ? "true" : "false");
|
||||
if (dropped || duplicate) {
|
||||
hil_trace_eventf("fault_injected", "\"fault\":\"%s\",\"batch_id\":%u,\"index\":%u",
|
||||
dropped ? "drop_chunk" : "duplicate_chunk", batch_id, i);
|
||||
}
|
||||
all_ok = all_ok && ok;
|
||||
if (!ok) {
|
||||
note_fault(g_sender_faults, g_sender_last_error, g_sender_last_error_utc, g_sender_last_error_ms, FaultType::LoraTx);
|
||||
@@ -502,26 +607,47 @@ static bool send_batch_payload(const uint8_t *data, size_t len, uint32_t ts_for_
|
||||
}
|
||||
|
||||
static void send_batch_ack(uint16_t batch_id, uint16_t sender_id) {
|
||||
if (hil_fault_take(HilFault::SuppressAck)) {
|
||||
hil_trace_eventf("fault_injected", "\"fault\":\"suppress_ack\",\"batch_id\":%u", batch_id);
|
||||
hil_trace_eventf("ack_tx", "\"batch_id\":%u,\"sender\":%u,\"ok\":false,\"suppressed\":true", batch_id, sender_id);
|
||||
lora_receive_continuous();
|
||||
return;
|
||||
}
|
||||
if (hil_fault_take(HilFault::DelayAck)) {
|
||||
uint32_t delay_ms = hil_fault_delay_ms();
|
||||
hil_trace_eventf("fault_injected", "\"fault\":\"delay_ack\",\"batch_id\":%u,\"delay_ms\":%lu",
|
||||
batch_id, static_cast<unsigned long>(delay_ms));
|
||||
delay(delay_ms);
|
||||
}
|
||||
LoraPacket ack = {};
|
||||
ack.protocol_version = PROTOCOL_VERSION;
|
||||
ack.role = DeviceRole::Receiver;
|
||||
ack.device_id_short = g_short_id;
|
||||
ack.payload_type = PayloadType::Ack;
|
||||
ack.payload_len = 6;
|
||||
write_u16_le(&ack.payload[0], batch_id);
|
||||
uint16_t transmitted_batch_id = batch_id;
|
||||
if (hil_fault_take(HilFault::WrongAckBatch)) {
|
||||
transmitted_batch_id = static_cast<uint16_t>(batch_id + 1);
|
||||
hil_trace_eventf("fault_injected", "\"fault\":\"wrong_ack_batch\",\"batch_id\":%u,\"sent_batch_id\":%u",
|
||||
batch_id, transmitted_batch_id);
|
||||
}
|
||||
write_u16_le(&ack.payload[0], transmitted_batch_id);
|
||||
write_u16_le(&ack.payload[2], sender_id);
|
||||
write_u16_le(&ack.payload[4], g_short_id);
|
||||
uint8_t repeats = ACK_REPEAT_COUNT == 0 ? 1 : ACK_REPEAT_COUNT;
|
||||
bool all_ok = true;
|
||||
for (uint8_t i = 0; i < repeats; ++i) {
|
||||
if (SERIAL_DEBUG_MODE) {
|
||||
serial_debug_printf("ack: tx repeat %u/%u batch_id=%u", static_cast<unsigned>(i + 1),
|
||||
static_cast<unsigned>(repeats), batch_id);
|
||||
}
|
||||
lora_send(ack);
|
||||
all_ok = lora_send(ack) && all_ok;
|
||||
if (i + 1 < repeats && ACK_REPEAT_DELAY_MS > 0) {
|
||||
delay(ACK_REPEAT_DELAY_MS);
|
||||
}
|
||||
}
|
||||
hil_trace_eventf("ack_tx", "\"batch_id\":%u,\"sent_batch_id\":%u,\"sender\":%u,\"repeats\":%u,\"ok\":%s",
|
||||
batch_id, transmitted_batch_id, sender_id, repeats, all_ok ? "true" : "false");
|
||||
lora_receive_continuous();
|
||||
}
|
||||
|
||||
@@ -543,6 +669,8 @@ static bool prepare_inflight_from_queue() {
|
||||
g_inflight_samples[i] = batch->samples[i];
|
||||
}
|
||||
g_inflight_active = true;
|
||||
hil_trace_eventf("batch_created", "\"batch_id\":%u,\"samples\":%u,\"queue\":%u",
|
||||
g_inflight_batch_id, g_inflight_count, g_batch_count);
|
||||
return true;
|
||||
}
|
||||
|
||||
@@ -576,8 +704,13 @@ static bool send_inflight_batch(uint32_t ts_for_display) {
|
||||
size_t encoded_len = 0;
|
||||
uint32_t encode_start = millis();
|
||||
if (!encode_batch(input, encoded, sizeof(encoded), &encoded_len)) {
|
||||
hil_trace_eventf("payload_encode", "\"batch_id\":%u,\"ok\":false,\"samples\":%u",
|
||||
g_inflight_batch_id, g_inflight_count);
|
||||
return false;
|
||||
}
|
||||
hil_trace_eventf("payload_encode", "\"batch_id\":%u,\"ok\":true,\"samples\":%u,\"len\":%u,\"crc32\":%lu",
|
||||
g_inflight_batch_id, g_inflight_count, static_cast<unsigned>(encoded_len),
|
||||
static_cast<unsigned long>(hil_crc32(encoded, encoded_len)));
|
||||
uint32_t encode_ms = millis() - encode_start;
|
||||
if (SERIAL_DEBUG_MODE) {
|
||||
serial_debug_printf("tx: batch_id=%u count=%u bin_len=%u", g_inflight_batch_id, g_inflight_count,
|
||||
@@ -628,7 +761,7 @@ static bool resend_inflight_batch(uint32_t ts_for_display) {
|
||||
|
||||
static void finish_inflight_batch() {
|
||||
if (g_batch_count > 0) {
|
||||
batch_queue_drop_oldest();
|
||||
batch_queue_remove_oldest(false);
|
||||
}
|
||||
g_batch_ack_pending = false;
|
||||
g_batch_retry_count = 0;
|
||||
@@ -661,9 +794,21 @@ static bool process_batch_packet(const LoraPacket &pkt, BatchInput &out_batch, b
|
||||
const uint8_t *chunk_data = &pkt.payload[BATCH_HEADER_SIZE];
|
||||
size_t chunk_len = pkt.payload_len - BATCH_HEADER_SIZE;
|
||||
uint32_t now_ms = millis();
|
||||
hil_trace_eventf("chunk_rx", "\"batch_id\":%u,\"index\":%u,\"count\":%u,\"len\":%u,\"crc32\":%lu",
|
||||
batch_id, chunk_index, chunk_count, static_cast<unsigned>(chunk_len),
|
||||
static_cast<unsigned long>(hil_crc32(chunk_data, chunk_len)));
|
||||
|
||||
if (!g_batch_rx.active || batch_id != g_batch_rx.batch_id || (now_ms - g_batch_rx.last_rx_ms > g_batch_rx.timeout_ms)) {
|
||||
bool rx_timed_out = g_batch_rx.active && (now_ms - g_batch_rx.last_rx_ms > g_batch_rx.timeout_ms);
|
||||
bool batch_changed = g_batch_rx.active && batch_id != g_batch_rx.batch_id;
|
||||
if (rx_timed_out || batch_changed) {
|
||||
hil_trace_eventf("reassembly_incomplete", "\"batch_id\":%u,\"received\":%u,\"expected_chunks\":%u,\"reason\":\"%s\"",
|
||||
g_batch_rx.batch_id, g_batch_rx.received_len, g_batch_rx.expected_chunks,
|
||||
rx_timed_out ? "timeout" : "batch_changed");
|
||||
}
|
||||
if (!g_batch_rx.active || batch_changed || rx_timed_out) {
|
||||
if (chunk_index != 0) {
|
||||
hil_trace_eventf("reassembly_incomplete", "\"batch_id\":%u,\"index\":%u,\"reason\":\"missing_first_chunk\"",
|
||||
batch_id, chunk_index);
|
||||
reset_batch_rx();
|
||||
return false;
|
||||
}
|
||||
@@ -681,11 +826,14 @@ static bool process_batch_packet(const LoraPacket &pkt, BatchInput &out_batch, b
|
||||
}
|
||||
|
||||
if (!g_batch_rx.active || chunk_index != g_batch_rx.next_index || chunk_count != g_batch_rx.expected_chunks) {
|
||||
hil_trace_eventf("reassembly_incomplete", "\"batch_id\":%u,\"index\":%u,\"expected_index\":%u,\"reason\":\"sequence\"",
|
||||
batch_id, chunk_index, g_batch_rx.next_index);
|
||||
reset_batch_rx();
|
||||
return false;
|
||||
}
|
||||
|
||||
if (g_batch_rx.received_len + chunk_len > g_batch_rx.total_len || g_batch_rx.received_len + chunk_len > BATCH_MAX_COMPRESSED) {
|
||||
hil_trace_eventf("reassembly_incomplete", "\"batch_id\":%u,\"reason\":\"length\"", batch_id);
|
||||
reset_batch_rx();
|
||||
return false;
|
||||
}
|
||||
@@ -698,10 +846,16 @@ static bool process_batch_packet(const LoraPacket &pkt, BatchInput &out_batch, b
|
||||
if (g_batch_rx.next_index == g_batch_rx.expected_chunks && g_batch_rx.received_len == g_batch_rx.total_len) {
|
||||
if (!decode_batch(g_batch_rx.buffer, g_batch_rx.received_len, &out_batch)) {
|
||||
decode_error = true;
|
||||
hil_trace_eventf("payload_decode", "\"batch_id\":%u,\"ok\":false,\"len\":%u",
|
||||
batch_id, g_batch_rx.received_len);
|
||||
reset_batch_rx();
|
||||
return false;
|
||||
}
|
||||
out_batch_id = batch_id;
|
||||
hil_trace_eventf("reassembly_complete", "\"batch_id\":%u,\"chunks\":%u,\"len\":%u,\"crc32\":%lu",
|
||||
batch_id, g_batch_rx.expected_chunks, g_batch_rx.received_len,
|
||||
static_cast<unsigned long>(hil_crc32(g_batch_rx.buffer, g_batch_rx.received_len)));
|
||||
hil_trace_eventf("payload_decode", "\"batch_id\":%u,\"ok\":true,\"samples\":%u", batch_id, out_batch.n);
|
||||
reset_batch_rx();
|
||||
return true;
|
||||
}
|
||||
@@ -720,6 +874,11 @@ void setup() {
|
||||
g_boot_ms = millis();
|
||||
g_role = detect_role();
|
||||
init_device_ids(g_short_id, g_device_id, sizeof(g_device_id));
|
||||
int reset_reason = 0;
|
||||
#ifdef ARDUINO_ARCH_ESP32
|
||||
reset_reason = static_cast<int>(esp_reset_reason());
|
||||
#endif
|
||||
hil_trace_init(g_role, g_short_id, reset_reason);
|
||||
display_set_role(g_role);
|
||||
if (SERIAL_DEBUG_MODE) {
|
||||
#ifdef ARDUINO_ARCH_ESP32
|
||||
@@ -739,6 +898,11 @@ void setup() {
|
||||
power_sender_init();
|
||||
power_configure_unused_pins_sender();
|
||||
meter_init();
|
||||
#ifdef ARDUINO_ARCH_ESP32
|
||||
if (!meter_reader_start()) {
|
||||
serial_debug_printf("meter: reader task unavailable, using inline polling");
|
||||
}
|
||||
#endif
|
||||
g_last_sample_ms = millis() - METER_SAMPLE_INTERVAL_MS;
|
||||
g_last_send_ms = millis();
|
||||
update_battery_cache();
|
||||
@@ -779,7 +943,9 @@ void setup() {
|
||||
|
||||
static void sender_loop() {
|
||||
watchdog_kick();
|
||||
hil_trace_poll_commands();
|
||||
uint32_t now_ms = millis();
|
||||
hil_trace_health(g_batch_count, g_build_count, g_batch_retry_count);
|
||||
display_set_sender_queue(g_batch_count, g_build_count > 0);
|
||||
display_set_sender_batches(g_last_acked_batch_id, g_batch_id);
|
||||
if (SERIAL_DEBUG_MODE && now_ms - g_last_debug_log_ms >= 5000) {
|
||||
@@ -794,23 +960,7 @@ static void sender_loop() {
|
||||
g_batch_retry_count);
|
||||
}
|
||||
|
||||
const char *frame = nullptr;
|
||||
size_t frame_len = 0;
|
||||
if (meter_poll_frame(frame, frame_len)) {
|
||||
MeterData parsed = {};
|
||||
parsed.energy_total_kwh = NAN;
|
||||
parsed.total_power_w = NAN;
|
||||
parsed.phase_power_w[0] = NAN;
|
||||
parsed.phase_power_w[1] = NAN;
|
||||
parsed.phase_power_w[2] = NAN;
|
||||
parsed.valid = false;
|
||||
if (meter_parse_frame(frame, frame_len, parsed)) {
|
||||
g_last_meter_data = parsed;
|
||||
g_last_meter_valid = true;
|
||||
g_last_meter_rx_ms = now_ms;
|
||||
g_meter_stale_seconds = 0;
|
||||
}
|
||||
}
|
||||
meter_reader_pump(now_ms);
|
||||
|
||||
if (now_ms - g_last_sample_ms >= METER_SAMPLE_INTERVAL_MS) {
|
||||
g_last_sample_ms = now_ms;
|
||||
@@ -818,21 +968,28 @@ static void sender_loop() {
|
||||
data.short_id = g_short_id;
|
||||
strncpy(data.device_id, g_device_id, sizeof(data.device_id));
|
||||
|
||||
bool meter_ok = g_last_meter_valid;
|
||||
if (meter_ok) {
|
||||
uint32_t meter_age_ms = g_last_meter_valid ? now_ms - g_last_meter_rx_ms : UINT32_MAX;
|
||||
MeterHealthEvaluation meter_health = meter_health_evaluate(
|
||||
g_meter_health_state, g_last_meter_valid, meter_age_ms, METER_SAMPLE_MAX_AGE_MS);
|
||||
bool meter_ok = meter_health.ok;
|
||||
if (g_last_meter_valid) {
|
||||
data.energy_total_kwh = g_last_meter_data.energy_total_kwh;
|
||||
data.total_power_w = g_last_meter_data.total_power_w;
|
||||
data.phase_power_w[0] = g_last_meter_data.phase_power_w[0];
|
||||
data.phase_power_w[1] = g_last_meter_data.phase_power_w[1];
|
||||
data.phase_power_w[2] = g_last_meter_data.phase_power_w[2];
|
||||
uint32_t age_ms = now_ms - g_last_meter_rx_ms;
|
||||
g_meter_stale_seconds = age_ms >= 1000 ? (age_ms / 1000) : 0;
|
||||
g_meter_stale_seconds = meter_age_ms >= 1000 ? (meter_age_ms / 1000) : 0;
|
||||
} else {
|
||||
g_meter_stale_seconds++;
|
||||
}
|
||||
if (!meter_ok) {
|
||||
if (meter_health.fault_started) {
|
||||
note_fault(g_sender_faults, g_sender_last_error, g_sender_last_error_utc, g_sender_last_error_ms, FaultType::MeterRead);
|
||||
display_set_last_error(g_sender_last_error, g_sender_last_error_utc, g_sender_last_error_ms);
|
||||
hil_trace_eventf("meter_fault", "\"state\":\"active\",\"classification\":\"%s\",\"stale_s\":%lu",
|
||||
meter_health_classification_text(meter_health.classification),
|
||||
static_cast<unsigned long>(g_meter_stale_seconds));
|
||||
} else if (meter_health.recovered) {
|
||||
hil_trace_event("meter_fault", "\"state\":\"recovered\"");
|
||||
}
|
||||
if (g_build_count == 0 && battery_sample_due(now_ms)) {
|
||||
update_battery_cache();
|
||||
@@ -844,12 +1001,19 @@ static void sender_loop() {
|
||||
uint32_t now_utc = time_get_utc();
|
||||
data.ts_utc = now_utc > 0 ? now_utc : millis() / 1000;
|
||||
data.valid = meter_ok;
|
||||
hil_trace_eventf("meter_sample", "\"ok\":%s,\"classification\":\"%s\",\"ts\":%lu,\"stale_s\":%lu",
|
||||
meter_ok ? "true" : "false",
|
||||
meter_health_classification_text(meter_health.classification),
|
||||
static_cast<unsigned long>(data.ts_utc),
|
||||
static_cast<unsigned long>(g_meter_stale_seconds));
|
||||
|
||||
g_last_sample_ts_utc = data.ts_utc;
|
||||
g_build_samples[g_build_count++] = data;
|
||||
if (g_build_count >= METER_BATCH_MAX_SAMPLES) {
|
||||
batch_queue_enqueue(g_build_samples, g_build_count);
|
||||
g_build_count = 0;
|
||||
if (meter_ok) {
|
||||
g_last_sample_ts_utc = data.ts_utc;
|
||||
g_build_samples[g_build_count++] = data;
|
||||
if (g_build_count >= METER_BATCH_MAX_SAMPLES) {
|
||||
batch_queue_enqueue(g_build_samples, g_build_count);
|
||||
g_build_count = 0;
|
||||
}
|
||||
}
|
||||
display_set_last_meter(data);
|
||||
display_set_last_read(meter_ok, data.ts_utc);
|
||||
@@ -899,6 +1063,7 @@ static void sender_loop() {
|
||||
if (ack_sender == g_short_id && ack_receiver == ack_pkt.device_id_short &&
|
||||
g_batch_ack_pending && ack_id == g_last_sent_batch_id) {
|
||||
g_last_acked_batch_id = ack_id;
|
||||
hil_trace_eventf("ack_rx", "\"batch_id\":%u,\"ok\":true,\"receiver\":%u", ack_id, ack_receiver);
|
||||
serial_debug_printf("ack: rx ok batch_id=%u", ack_id);
|
||||
finish_inflight_batch();
|
||||
} else {
|
||||
@@ -907,6 +1072,8 @@ static void sender_loop() {
|
||||
} else if (ack_id != g_last_sent_batch_id) {
|
||||
sender_note_rx_reject(RxRejectReason::BatchIdMismatch, "ack");
|
||||
}
|
||||
hil_trace_eventf("ack_rx", "\"batch_id\":%u,\"ok\":false,\"expected_batch_id\":%u,\"sender\":%u,\"receiver\":%u",
|
||||
ack_id, g_last_sent_batch_id, ack_sender, ack_receiver);
|
||||
if (SERIAL_DEBUG_MODE) {
|
||||
serial_debug_printf("ack: reject batch_id=%u sender=%u receiver=%u exp_batch=%u exp_sender=%u",
|
||||
ack_id, ack_sender, ack_receiver, g_last_sent_batch_id, g_short_id);
|
||||
@@ -917,6 +1084,8 @@ static void sender_loop() {
|
||||
|
||||
bool timesync_due = (!g_batch_ack_pending && sender_timesync_window_due());
|
||||
if (timesync_due) {
|
||||
hil_trace_eventf("time_bootstrap", "\"stage\":\"request\",\"window_ms\":%lu",
|
||||
static_cast<unsigned long>((g_sender_timesync_mode == 2) ? SENDER_TIMESYNC_ACQUIRE_WINDOW_MS : SENDER_TIMESYNC_WINDOW_MS));
|
||||
LoraPacket rx = {};
|
||||
uint32_t rx_start = millis();
|
||||
uint32_t window_ms = (g_sender_timesync_mode == 2) ? SENDER_TIMESYNC_ACQUIRE_WINDOW_MS : SENDER_TIMESYNC_WINDOW_MS;
|
||||
@@ -941,6 +1110,8 @@ static void sender_loop() {
|
||||
display_set_last_error(FaultType::None, 0, 0);
|
||||
}
|
||||
serial_debug_printf("timesync: rx ok window_ms=%lu", static_cast<unsigned long>(window_ms));
|
||||
hil_trace_eventf("time_bootstrap", "\"stage\":\"complete\",\"ok\":true,\"utc\":%lu,\"receiver\":%u",
|
||||
static_cast<unsigned long>(time_get_utc()), rx.device_id_short);
|
||||
} else {
|
||||
sender_note_rx_reject(RxRejectReason::LengthMismatch, "timesync");
|
||||
if (SERIAL_DEBUG_MODE) {
|
||||
@@ -961,9 +1132,13 @@ static void sender_loop() {
|
||||
if (g_batch_ack_pending && (now_ms - g_last_batch_send_ms >= g_batch_ack_timeout_ms)) {
|
||||
if (g_batch_retry_count < BATCH_MAX_RETRIES) {
|
||||
g_batch_retry_count++;
|
||||
hil_trace_eventf("retry", "\"batch_id\":%u,\"retry\":%u,\"reason\":\"ack_timeout\"",
|
||||
g_inflight_batch_id, g_batch_retry_count);
|
||||
serial_debug_printf("ack: timeout batch_id=%u retry=%u", g_inflight_batch_id, g_batch_retry_count);
|
||||
resend_inflight_batch(last_sample_ts());
|
||||
} else {
|
||||
hil_trace_eventf("timeout", "\"batch_id\":%u,\"retries\":%u,\"kind\":\"ack\"",
|
||||
g_inflight_batch_id, g_batch_retry_count);
|
||||
serial_debug_printf("ack: failed batch_id=%u policy=%s", g_inflight_batch_id,
|
||||
BATCH_RETRY_POLICY == BatchRetryPolicy::Drop ? "drop" : "keep");
|
||||
if (BATCH_RETRY_POLICY == BatchRetryPolicy::Drop) {
|
||||
@@ -1002,6 +1177,8 @@ static void sender_loop() {
|
||||
|
||||
static void receiver_loop() {
|
||||
watchdog_kick();
|
||||
hil_trace_poll_commands();
|
||||
hil_trace_health(0, 0, 0);
|
||||
if (g_last_timesync_ms == 0) {
|
||||
g_last_timesync_ms = millis() - (TIME_SYNC_INTERVAL_SEC * 1000UL - TIME_SYNC_OFFSET_MS);
|
||||
}
|
||||
@@ -1069,6 +1246,7 @@ static void receiver_loop() {
|
||||
}
|
||||
bool duplicate = sender_idx >= 0 && g_last_batch_id_rx[sender_idx] == batch_id;
|
||||
if (duplicate) {
|
||||
hil_trace_eventf("duplicate", "\"batch_id\":%u,\"sender\":%u", batch_id, pkt.device_id_short);
|
||||
send_batch_ack(batch_id, pkt.device_id_short);
|
||||
} else {
|
||||
g_last_batch_id_rx[sender_idx] = batch_id;
|
||||
@@ -1172,23 +1350,29 @@ static void receiver_loop() {
|
||||
}
|
||||
}
|
||||
if (burst_sent) {
|
||||
if (!time_send_timesync(g_short_id)) {
|
||||
bool time_sent = time_send_timesync(g_short_id);
|
||||
if (!time_sent) {
|
||||
note_fault(g_receiver_faults, g_receiver_last_error, g_receiver_last_error_utc, g_receiver_last_error_ms, FaultType::LoraTx);
|
||||
display_set_last_error(g_receiver_last_error, g_receiver_last_error_utc, g_receiver_last_error_ms);
|
||||
}
|
||||
if (SERIAL_DEBUG_MODE) {
|
||||
serial_debug_printf("timesync: tx burst");
|
||||
}
|
||||
hil_trace_eventf("time_bootstrap", "\"stage\":\"transmit\",\"mode\":\"burst\",\"ok\":%s,\"utc\":%lu",
|
||||
time_sent ? "true" : "false", static_cast<unsigned long>(time_get_utc()));
|
||||
g_last_timesync_ms = now_ms;
|
||||
} else if (now_ms - g_last_timesync_ms > interval_sec * 1000UL) {
|
||||
g_last_timesync_ms = now_ms;
|
||||
if (!time_send_timesync(g_short_id)) {
|
||||
bool time_sent = time_send_timesync(g_short_id);
|
||||
if (!time_sent) {
|
||||
note_fault(g_receiver_faults, g_receiver_last_error, g_receiver_last_error_utc, g_receiver_last_error_ms, FaultType::LoraTx);
|
||||
display_set_last_error(g_receiver_last_error, g_receiver_last_error_utc, g_receiver_last_error_ms);
|
||||
}
|
||||
if (SERIAL_DEBUG_MODE) {
|
||||
serial_debug_printf("timesync: tx normal");
|
||||
}
|
||||
hil_trace_eventf("time_bootstrap", "\"stage\":\"transmit\",\"mode\":\"normal\",\"ok\":%s,\"utc\":%lu",
|
||||
time_sent ? "true" : "false", static_cast<unsigned long>(time_get_utc()));
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
Reference in New Issue
Block a user