mirror of
https://github.com/agessaman/MeshCore.git
synced 2026-08-24 18:10:03 +00:00
feat(mesh): enhance packet logging with human-readable RX/TX output
This commit is contained in:
@@ -3,6 +3,9 @@
|
||||
#include <math.h> // for lroundf()
|
||||
#include <stdlib.h> // for qsort()
|
||||
#include <helpers/RxReservePacketManager.h>
|
||||
#if MESH_PACKET_LOGGING
|
||||
#include <helpers/SerialPacketLog.h>
|
||||
#endif
|
||||
#if defined(WITH_MQTT_NEIGHBORS)
|
||||
#include <helpers/MQTTConnectionPolicy.h> // kSyncedClockEpoch
|
||||
#endif
|
||||
@@ -512,16 +515,14 @@ const char *MyMesh::getLogDateTime() {
|
||||
|
||||
void MyMesh::logRxRaw(float snr, float rssi, const uint8_t raw[], int len) {
|
||||
#if MESH_PACKET_LOGGING
|
||||
if (Serial.availableForWrite() > 0) {
|
||||
{
|
||||
// SNR in quarter-dB integer units: the radio's native resolution, and no float
|
||||
// formatting, which is unreliable on some platform cores.
|
||||
char hdr[56];
|
||||
snprintf(hdr, sizeof(hdr), " RAW: snr_q=%d rssi=%d len=%d hex=",
|
||||
(int)lroundf(snr * 4.0f), (int)lroundf(rssi), len);
|
||||
Serial.print(getLogDateTime());
|
||||
Serial.print(hdr);
|
||||
mesh::Utils::printHex(Serial, raw, len);
|
||||
Serial.println();
|
||||
SerialLogLine<> line;
|
||||
line.printf("%s RAW: snr_q=%d rssi=%d len=%d hex=", getLogDateTime(),
|
||||
(int)lroundf(snr * 4.0f), (int)lroundf(rssi), len);
|
||||
line.hex(raw, len);
|
||||
line.flush(Serial);
|
||||
}
|
||||
#endif
|
||||
|
||||
|
||||
@@ -1,5 +1,7 @@
|
||||
#include <Arduino.h> // needed for PlatformIO
|
||||
#include <Mesh.h>
|
||||
#include <helpers/SerialPacketLog.h>
|
||||
#include <helpers/TaskWatchdog.h>
|
||||
|
||||
#include "MyMesh.h"
|
||||
|
||||
@@ -37,6 +39,7 @@ static unsigned long userBtnDownAt = 0;
|
||||
|
||||
void setup() {
|
||||
Serial.begin(115200);
|
||||
serialLogBegin();
|
||||
delay(1000);
|
||||
|
||||
board.begin();
|
||||
@@ -125,9 +128,14 @@ void setup() {
|
||||
#endif
|
||||
|
||||
board.onBootComplete();
|
||||
|
||||
// Subscribed last so a slow boot can't trip it.
|
||||
taskWatchdogBegin();
|
||||
}
|
||||
|
||||
void loop() {
|
||||
taskWatchdogFeed();
|
||||
|
||||
// Handle Serial CLI
|
||||
int len = strlen(command);
|
||||
while (Serial.available() && len < sizeof(command)-1) {
|
||||
@@ -135,7 +143,7 @@ void loop() {
|
||||
if (c != '\n') {
|
||||
command[len++] = c;
|
||||
command[len] = 0;
|
||||
Serial.print(c);
|
||||
serialLogEmit(Serial, &c, 1); // echo, but never block on a host that stopped reading
|
||||
}
|
||||
if (c == '\r') break;
|
||||
}
|
||||
@@ -144,7 +152,7 @@ void loop() {
|
||||
}
|
||||
|
||||
if (len > 0 && command[len - 1] == '\r') { // received complete line
|
||||
Serial.print('\n');
|
||||
serialLogEmit(Serial, "\n", 1);
|
||||
command[len - 1] = 0; // replace newline with C string null terminator
|
||||
char reply[160];
|
||||
reply[0] = 0;
|
||||
@@ -156,7 +164,9 @@ void loop() {
|
||||
the_mesh.handleCommand(0, command, reply); // NOTE: there is no sender_timestamp via serial!
|
||||
#endif
|
||||
if (reply[0]) {
|
||||
Serial.print(" -> "); Serial.println(reply);
|
||||
SerialLogLine<192> line;
|
||||
line.printf(" -> %s", reply);
|
||||
line.flush(Serial);
|
||||
}
|
||||
|
||||
command[0] = 0; // reset command buffer
|
||||
@@ -206,6 +216,7 @@ void loop() {
|
||||
#else
|
||||
if (the_mesh.millisHasNowPassed(POWERSAVING_FIRSTSLEEP_SECS * 1000)) { // To check if it is time to sleep
|
||||
board.sleep(30); // Sleep. Wake up after a while or when receiving a LoRa packet
|
||||
taskWatchdogFeed(); // sleeping is not a wedge
|
||||
}
|
||||
#endif
|
||||
}
|
||||
|
||||
+31
-24
@@ -1,7 +1,8 @@
|
||||
#include "Dispatcher.h"
|
||||
|
||||
#if MESH_PACKET_LOGGING
|
||||
#if MESH_PACKET_LOGGING_TEXT
|
||||
#include <Arduino.h>
|
||||
#include <helpers/SerialPacketLog.h>
|
||||
#endif
|
||||
|
||||
#include <math.h>
|
||||
@@ -250,22 +251,26 @@ void Dispatcher::checkRecv() {
|
||||
}
|
||||
}
|
||||
if (pkt) {
|
||||
#if MESH_PACKET_LOGGING
|
||||
Serial.print(getLogDateTime());
|
||||
Serial.printf(": RX, len=%d (type=%d, route=%s, payload_len=%d) SNR=%d RSSI=%d score=%d time=%d",
|
||||
pkt->getRawLength(), pkt->getPayloadType(), pkt->isRouteDirect() ? "D" : "F", pkt->payload_len,
|
||||
(int)pkt->getSNR(), (int)_radio->getLastRSSI(), (int)(score*1000), air_time);
|
||||
#if MESH_PACKET_LOGGING_TEXT
|
||||
{
|
||||
SerialLogLine<192> line;
|
||||
line.printf("%s: RX, len=%d (type=%d, route=%s, payload_len=%d) SNR=%d RSSI=%d score=%d time=%d",
|
||||
getLogDateTime(), pkt->getRawLength(), pkt->getPayloadType(),
|
||||
pkt->isRouteDirect() ? "D" : "F", pkt->payload_len,
|
||||
(int)pkt->getSNR(), (int)_radio->getLastRSSI(), (int)(score*1000), air_time);
|
||||
|
||||
static uint8_t packet_hash[MAX_HASH_SIZE];
|
||||
pkt->calculatePacketHash(packet_hash);
|
||||
Serial.print(" hash=");
|
||||
mesh::Utils::printHex(Serial, packet_hash, MAX_HASH_SIZE);
|
||||
uint8_t packet_hash[MAX_HASH_SIZE];
|
||||
pkt->calculatePacketHash(packet_hash);
|
||||
line.printf(" hash=");
|
||||
line.hex(packet_hash, MAX_HASH_SIZE);
|
||||
|
||||
if (pkt->getPayloadType() == PAYLOAD_TYPE_PATH || pkt->getPayloadType() == PAYLOAD_TYPE_REQ
|
||||
|| pkt->getPayloadType() == PAYLOAD_TYPE_RESPONSE || pkt->getPayloadType() == PAYLOAD_TYPE_TXT_MSG) {
|
||||
Serial.printf(" [%02X -> %02X]\n", (uint32_t)pkt->payload[1], (uint32_t)pkt->payload[0]);
|
||||
} else {
|
||||
Serial.printf("\n");
|
||||
if (pkt->getPayloadType() == PAYLOAD_TYPE_PATH || pkt->getPayloadType() == PAYLOAD_TYPE_REQ
|
||||
|| pkt->getPayloadType() == PAYLOAD_TYPE_RESPONSE || pkt->getPayloadType() == PAYLOAD_TYPE_TXT_MSG) {
|
||||
// No spaces around the arrow: a host parser must be able to split CLI replies on
|
||||
// "->" without colliding with log lines.
|
||||
line.printf(" [%02X>%02X]", (uint32_t)pkt->payload[1], (uint32_t)pkt->payload[0]);
|
||||
}
|
||||
line.flush(Serial);
|
||||
}
|
||||
#endif
|
||||
logRx(pkt, pkt->getRawLength(), score); // hook for custom logging
|
||||
@@ -371,15 +376,17 @@ void Dispatcher::checkSend() {
|
||||
}
|
||||
outbound_expiry = futureMillis(max_airtime);
|
||||
|
||||
#if MESH_PACKET_LOGGING
|
||||
Serial.print(getLogDateTime());
|
||||
Serial.printf(": TX, len=%d (type=%d, route=%s, payload_len=%d)",
|
||||
len, outbound->getPayloadType(), outbound->isRouteDirect() ? "D" : "F", outbound->payload_len);
|
||||
if (outbound->getPayloadType() == PAYLOAD_TYPE_PATH || outbound->getPayloadType() == PAYLOAD_TYPE_REQ
|
||||
|| outbound->getPayloadType() == PAYLOAD_TYPE_RESPONSE || outbound->getPayloadType() == PAYLOAD_TYPE_TXT_MSG) {
|
||||
Serial.printf(" [%02X -> %02X]\n", (uint32_t)outbound->payload[1], (uint32_t)outbound->payload[0]);
|
||||
} else {
|
||||
Serial.printf("\n");
|
||||
#if MESH_PACKET_LOGGING_TEXT
|
||||
{
|
||||
SerialLogLine<192> line;
|
||||
line.printf("%s: TX, len=%d (type=%d, route=%s, payload_len=%d)",
|
||||
getLogDateTime(), len, outbound->getPayloadType(),
|
||||
outbound->isRouteDirect() ? "D" : "F", outbound->payload_len);
|
||||
if (outbound->getPayloadType() == PAYLOAD_TYPE_PATH || outbound->getPayloadType() == PAYLOAD_TYPE_REQ
|
||||
|| outbound->getPayloadType() == PAYLOAD_TYPE_RESPONSE || outbound->getPayloadType() == PAYLOAD_TYPE_TXT_MSG) {
|
||||
line.printf(" [%02X>%02X]", (uint32_t)outbound->payload[1], (uint32_t)outbound->payload[0]);
|
||||
}
|
||||
line.flush(Serial);
|
||||
}
|
||||
#endif
|
||||
}
|
||||
|
||||
@@ -6,6 +6,13 @@
|
||||
#include <Utils.h>
|
||||
#include <string.h>
|
||||
|
||||
// The human-readable "RX,/TX," lines, split out from MESH_PACKET_LOGGING so a build can keep
|
||||
// the machine-readable RAW: dump without paying for both. Set to 0 alongside
|
||||
// MESH_PACKET_LOGGING=1 for capture builds; roughly halves serial volume.
|
||||
#ifndef MESH_PACKET_LOGGING_TEXT
|
||||
#define MESH_PACKET_LOGGING_TEXT MESH_PACKET_LOGGING
|
||||
#endif
|
||||
|
||||
namespace mesh {
|
||||
|
||||
/**
|
||||
|
||||
@@ -1799,7 +1799,9 @@ void CommonCLI::handleGetCmd(uint32_t sender_timestamp, char* command, char* rep
|
||||
if (!_board->canControlLoRaFemLna()) {
|
||||
strcpy(reply, "Error: unsupported");
|
||||
} else {
|
||||
sprintf(reply, "> %s", _board->isLoRaFemLnaEnabled() ? "on" : "off");
|
||||
// Same "> <pref> (chip: <live>)" shape as radio.rxgain, so one parser covers both.
|
||||
sprintf(reply, "> %s (chip: %s)", _prefs->radio_fem_rxgain ? "on" : "off",
|
||||
_board->isLoRaFemLnaEnabled() ? "on" : "off");
|
||||
}
|
||||
} else if (memcmp(config, "agc.reset.interval", 18) == 0) {
|
||||
sprintf(reply, "> %d", ((uint32_t) _prefs->agc_reset_interval) * 4);
|
||||
@@ -1833,7 +1835,9 @@ void CommonCLI::handleGetCmd(uint32_t sender_timestamp, char* command, char* rep
|
||||
sprintf(reply, "> %s (chip: %s)", _prefs->rx_boosted_gain ? "on" : "off",
|
||||
chip_gain ? "on" : "off");
|
||||
} else {
|
||||
sprintf(reply, "> %s", _prefs->rx_boosted_gain ? "on" : "off");
|
||||
// Explicit rather than a shorter reply: "can't read it" and "reads back off" have to
|
||||
// stay distinguishable to anything checking the radio didn't silently reset.
|
||||
sprintf(reply, "> %s (chip: n/a)", _prefs->rx_boosted_gain ? "on" : "off");
|
||||
}
|
||||
} else if (memcmp(config, "radio.fem.txgain", 16) == 0) {
|
||||
if (!_board->canControlLoRaFemPaGain()) {
|
||||
|
||||
@@ -325,7 +325,7 @@ public:
|
||||
};
|
||||
|
||||
// Reads boosted gain back off the radio. Returns false when the build can't read it,
|
||||
// in which case 'get radio.rxgain' reports the pref alone.
|
||||
// in which case 'get radio.rxgain' reports the pref with "(chip: n/a)".
|
||||
virtual bool getRxBoostedGain(bool& enabled) {
|
||||
(void)enabled;
|
||||
return false;
|
||||
|
||||
@@ -0,0 +1,136 @@
|
||||
#pragma once
|
||||
|
||||
#include <Arduino.h>
|
||||
#include <stdarg.h>
|
||||
#include <stddef.h>
|
||||
#include <stdint.h>
|
||||
#include <stdio.h>
|
||||
#include <string.h>
|
||||
|
||||
// Bounded serial writer for the packet-logging paths.
|
||||
//
|
||||
// USBCDC::write() (arduino-esp32 2.0.17) spins with no timeout when the CDC TX FIFO is
|
||||
// full and the host still has the port open but has stopped reading it:
|
||||
//
|
||||
// size_t space = tud_cdc_n_write_available(itf);
|
||||
// if(!space){ tud_cdc_n_write_flush(itf); continue; }
|
||||
//
|
||||
// The FIFO is 64 bytes (CONFIG_TINYUSB_CDC_TX_BUFSIZE), so every packet log line needs the
|
||||
// host to drain it several times mid-write. The spin runs in the Arduino loop task, which
|
||||
// is pinned to core 1, and the task watchdog only covers the core 0 idle task
|
||||
// (CONFIG_ESP_TASK_WDT_CHECK_IDLE_TASK_CPU1 is unset) — so the node simply goes quiet: no
|
||||
// CLI, no logging, no crash, no reboot, port still enumerated.
|
||||
//
|
||||
// Writes here only ever hand the port as many bytes as it reports it can take, so a host
|
||||
// that stops draining costs a dropped log line instead of the mesh loop.
|
||||
|
||||
// Enough for a hex dump of a 255-byte packet plus its header.
|
||||
#ifndef SERIAL_LOG_LINE_MAX
|
||||
#define SERIAL_LOG_LINE_MAX 640
|
||||
#endif
|
||||
|
||||
// Only spent once a line is already part-written, to avoid truncating it.
|
||||
#ifndef SERIAL_LOG_WRITE_BUDGET_MS
|
||||
#define SERIAL_LOG_WRITE_BUDGET_MS 20
|
||||
#endif
|
||||
|
||||
// Log lines lost since the last DROP: marker got through.
|
||||
inline uint32_t& serialLogDroppedCount() { static uint32_t n = 0; return n; }
|
||||
|
||||
// Whether the port has ever accepted output. An unattached port reports no room, exactly
|
||||
// like a wedged one, so counting drops before this is set would greet the first host to
|
||||
// connect with a tally of every line emitted since boot.
|
||||
inline bool& serialLogPortSeen() { static bool seen = false; return seen; }
|
||||
|
||||
// Pushes out whatever the port will take without blocking, waiting only until the budget
|
||||
// expires. Returns false if any of it had to be abandoned.
|
||||
template <class T> bool serialLogEmit(T& out, const char* data, size_t len) {
|
||||
if (out.availableForWrite() <= 0) return false; // host is not draining: drop now
|
||||
uint32_t start = millis();
|
||||
size_t sent = 0;
|
||||
while (sent < len) {
|
||||
int space = out.availableForWrite();
|
||||
if (space <= 0) {
|
||||
if ((uint32_t)(millis() - start) >= SERIAL_LOG_WRITE_BUDGET_MS) return false;
|
||||
delay(1); // yields to the USB task
|
||||
continue;
|
||||
}
|
||||
size_t n = (size_t)space;
|
||||
if (n > len - sent) n = len - sent;
|
||||
size_t written = out.write((const uint8_t *)(data + sent), n);
|
||||
if (written == 0) return false; // port closed
|
||||
sent += written;
|
||||
}
|
||||
serialLogPortSeen() = true;
|
||||
return true;
|
||||
}
|
||||
|
||||
template <size_t CAP = SERIAL_LOG_LINE_MAX>
|
||||
class SerialLogLine {
|
||||
public:
|
||||
void printf(const char* fmt, ...) {
|
||||
size_t room = capacity() - _len;
|
||||
if (room == 0) { _truncated = true; return; }
|
||||
|
||||
va_list args;
|
||||
va_start(args, fmt);
|
||||
int n = vsnprintf(&_buf[_len], room, fmt, args);
|
||||
va_end(args);
|
||||
if (n < 0) return;
|
||||
if ((size_t)n >= room) { // vsnprintf truncated; keep what fit, minus its terminator
|
||||
_len = capacity() - 1;
|
||||
_truncated = true;
|
||||
} else {
|
||||
_len += n;
|
||||
}
|
||||
}
|
||||
|
||||
void hex(const uint8_t* src, size_t len) {
|
||||
static const char hex_chars[] = "0123456789ABCDEF";
|
||||
while (len > 0) {
|
||||
if (_len + 2 > capacity()) { _truncated = true; return; }
|
||||
uint8_t b = *src++;
|
||||
_buf[_len++] = hex_chars[b >> 4];
|
||||
_buf[_len++] = hex_chars[b & 0x0F];
|
||||
len--;
|
||||
}
|
||||
}
|
||||
|
||||
// Terminates the line and pushes it out. Never blocks on a host that has stopped
|
||||
// reading. Returns false if the line was dropped or cut short.
|
||||
template <class T> bool flush(T& out) {
|
||||
bool complete = !_truncated;
|
||||
_buf[_len++] = '\r'; // CRLF, matching the Serial.println() these lines replaced
|
||||
_buf[_len++] = '\n';
|
||||
size_t len = _len;
|
||||
_len = 0;
|
||||
_truncated = false;
|
||||
|
||||
// Tell whoever is parsing that they are looking at a gap, not a quiet mesh.
|
||||
uint32_t& dropped = serialLogDroppedCount();
|
||||
if (dropped > 0) {
|
||||
char marker[24];
|
||||
int n = snprintf(marker, sizeof(marker), "DROP:%u\r\n", (unsigned)dropped);
|
||||
if (n > 0 && serialLogEmit(out, marker, (size_t)n)) dropped = 0;
|
||||
}
|
||||
|
||||
if (!serialLogEmit(out, _buf, len)) complete = false;
|
||||
if (!complete && serialLogPortSeen()) dropped++;
|
||||
return complete;
|
||||
}
|
||||
|
||||
private:
|
||||
size_t capacity() const { return CAP - 2; } // leaves room for the CRLF
|
||||
|
||||
char _buf[CAP];
|
||||
size_t _len = 0;
|
||||
bool _truncated = false;
|
||||
};
|
||||
|
||||
// USBCDC/HWCDC wait up to tx_timeout_ms (250 by default) just to take the TX lock, so a
|
||||
// write from another task can stall the mesh loop even when the FIFO has room.
|
||||
inline void serialLogBegin() {
|
||||
#if defined(ESP32_PLATFORM) && defined(ARDUINO_USB_CDC_ON_BOOT) && (ARDUINO_USB_CDC_ON_BOOT == 1)
|
||||
Serial.setTxTimeoutMs(0);
|
||||
#endif
|
||||
}
|
||||
@@ -0,0 +1,35 @@
|
||||
#pragma once
|
||||
|
||||
// Reboots the node if the main loop stops running.
|
||||
//
|
||||
// The ESP32 task watchdog is already compiled in (CONFIG_ESP_TASK_WDT=y, 5s, panic on
|
||||
// expiry), but it only watches the core 0 idle task —
|
||||
// CONFIG_ESP_TASK_WDT_CHECK_IDLE_TASK_CPU1 is unset and the Arduino loop task is pinned to
|
||||
// core 1 (ARDUINO_RUNNING_CORE=1). A loop that never returns is therefore invisible to it,
|
||||
// which is how a blocking USB CDC write can silence a node indefinitely with no crash and
|
||||
// no reboot (see SerialPacketLog.h). Subscribing the loop task itself closes that gap: a
|
||||
// wedge becomes a reboot and a fresh boot banner instead of an open-ended silence.
|
||||
//
|
||||
// Opt in per build with -D WITH_TASK_WATCHDOG_SECS=<seconds>. Pick a timeout well above the
|
||||
// longest legitimate loop stall (MQTT teardown, flash writes, board.sleep()); note that the
|
||||
// timeout is global to the watchdog, so this also relaxes it for the core 0 idle task.
|
||||
|
||||
#if defined(WITH_TASK_WATCHDOG_SECS) && defined(ESP32_PLATFORM)
|
||||
|
||||
#include <esp_task_wdt.h>
|
||||
|
||||
inline void taskWatchdogBegin() {
|
||||
esp_task_wdt_init(WITH_TASK_WATCHDOG_SECS, true); // panic => reboot
|
||||
esp_task_wdt_add(NULL); // watch the calling (loop) task
|
||||
}
|
||||
|
||||
inline void taskWatchdogFeed() {
|
||||
esp_task_wdt_reset();
|
||||
}
|
||||
|
||||
#else
|
||||
|
||||
inline void taskWatchdogBegin() { }
|
||||
inline void taskWatchdogFeed() { }
|
||||
|
||||
#endif
|
||||
@@ -5,6 +5,7 @@
|
||||
#include "../MQTTReplyFormat.h"
|
||||
#include "../MQTTRuntimeBufferLifecycle.h"
|
||||
#include "../MQTTTopicRouter.h"
|
||||
#include "../TaskWatchdog.h"
|
||||
#include "../TxtDataHelpers.h"
|
||||
#include <NTPClient.h>
|
||||
#include <WiFiUdp.h>
|
||||
@@ -1108,6 +1109,10 @@ void MQTTBridge::end() {
|
||||
}
|
||||
_lifecycle.tick(); // may fire StopTimedOut -> Stopped (dirty): releaseResources()
|
||||
if (!_lifecycle.isStopInProgress()) break;
|
||||
// A cooperative teardown runs the loop task out to the slot-scaled budget (up to ~53 s
|
||||
// on a 6-slot PSRAM board), which is far longer than any watchdog worth having. Waiting
|
||||
// here is not a wedge, so keep feeding it.
|
||||
taskWatchdogFeed();
|
||||
vTaskDelay(pdMS_TO_TICKS(20));
|
||||
}
|
||||
#else
|
||||
|
||||
@@ -0,0 +1,208 @@
|
||||
// The packet-logging writer exists because USBCDC::write() spins forever on a full TX FIFO
|
||||
// when the host has the port open but has stopped reading it, wedging the mesh loop with no
|
||||
// crash and no reboot. These cases pin the two properties that matter: it never waits on a
|
||||
// host that isn't draining, and a dropped line is reported rather than silently lost.
|
||||
#include <gtest/gtest.h>
|
||||
|
||||
#include <string>
|
||||
|
||||
#include "helpers/SerialPacketLog.h"
|
||||
|
||||
namespace {
|
||||
|
||||
// A CDC-like port with a bounded TX FIFO that refills only as fast as the host reads it.
|
||||
class FakePort : public Stream {
|
||||
public:
|
||||
explicit FakePort(size_t capacity = 64, size_t bytes_per_ms = 64)
|
||||
: _cap(capacity), _free(capacity), _rate(bytes_per_ms), _last_ms(millis()) { }
|
||||
|
||||
int availableForWrite() override {
|
||||
uint32_t now = millis();
|
||||
_free += (size_t)(now - _last_ms) * _rate;
|
||||
_last_ms = now;
|
||||
if (_free > _cap) _free = _cap;
|
||||
return (int)_free;
|
||||
}
|
||||
|
||||
size_t write(const uint8_t* buffer, size_t size) override {
|
||||
if (size > _free) size = _free; // a real port would block here instead
|
||||
_written.append((const char*)buffer, size);
|
||||
_free -= size;
|
||||
if (_written.size() >= _wedge_after) wedge();
|
||||
return size;
|
||||
}
|
||||
|
||||
// Host stops reading: the FIFO fills and never drains again.
|
||||
void wedge() { availableForWrite(); _rate = 0; _free = 0; }
|
||||
void wedgeAfter(size_t bytes) { _wedge_after = bytes; }
|
||||
|
||||
const std::string& written() const { return _written; }
|
||||
|
||||
private:
|
||||
size_t _cap, _free, _rate;
|
||||
size_t _wedge_after = (size_t)-1;
|
||||
uint32_t _last_ms;
|
||||
std::string _written;
|
||||
};
|
||||
|
||||
class SerialPacketLogTest : public ::testing::Test {
|
||||
protected:
|
||||
void SetUp() override {
|
||||
g_mock_millis = 1000;
|
||||
serialLogDroppedCount() = 0;
|
||||
serialLogPortSeen() = false;
|
||||
}
|
||||
|
||||
// Drops are only counted once the port has proven it can take output, so tests about
|
||||
// drop accounting have to get one line through first.
|
||||
static void primePort() {
|
||||
FakePort port(4096);
|
||||
SerialLogLine<> line;
|
||||
line.printf("primed");
|
||||
ASSERT_TRUE(line.flush(port));
|
||||
ASSERT_TRUE(serialLogPortSeen());
|
||||
}
|
||||
};
|
||||
|
||||
TEST_F(SerialPacketLogTest, WritesWholeLineThroughASmallFifo) {
|
||||
FakePort port; // 64-byte FIFO, so a hex dump needs several drains
|
||||
uint8_t raw[40];
|
||||
for (size_t i = 0; i < sizeof(raw); i++) raw[i] = (uint8_t)i;
|
||||
|
||||
SerialLogLine<> line;
|
||||
line.printf("12:00:00 - 1/1/2026 U RAW: snr_q=%d rssi=%d len=%d hex=", -22, -95, (int)sizeof(raw));
|
||||
line.hex(raw, sizeof(raw));
|
||||
EXPECT_TRUE(line.flush(port));
|
||||
|
||||
EXPECT_EQ('\n', port.written().back());
|
||||
EXPECT_NE(std::string::npos, port.written().find("snr_q=-22 rssi=-95 len=40 hex=000102"));
|
||||
EXPECT_EQ(0u, serialLogDroppedCount());
|
||||
}
|
||||
|
||||
TEST_F(SerialPacketLogTest, HexMatchesUppercaseWireFormat) {
|
||||
FakePort port(4096);
|
||||
const uint8_t raw[] = { 0x00, 0x0F, 0xAB, 0xFF };
|
||||
|
||||
SerialLogLine<> line;
|
||||
line.hex(raw, sizeof(raw));
|
||||
ASSERT_TRUE(line.flush(port));
|
||||
|
||||
EXPECT_EQ("000FABFF\r\n", port.written());
|
||||
}
|
||||
|
||||
// The wedge case: a host with the port open that has stopped reading must cost a line, not
|
||||
// the loop.
|
||||
TEST_F(SerialPacketLogTest, DropsImmediatelyWhenHostStoppedDraining) {
|
||||
primePort();
|
||||
FakePort port;
|
||||
port.wedge();
|
||||
|
||||
uint32_t before = millis();
|
||||
SerialLogLine<> line;
|
||||
line.printf("RAW: hex=");
|
||||
line.hex((const uint8_t*)"\x01\x02", 2);
|
||||
EXPECT_FALSE(line.flush(port));
|
||||
|
||||
EXPECT_EQ(before, millis()) << "must not wait at all on a port with no room";
|
||||
EXPECT_TRUE(port.written().empty());
|
||||
EXPECT_EQ(1u, serialLogDroppedCount());
|
||||
}
|
||||
|
||||
// Same host, but it stops reading part-way through a line: finishing it is worth a short
|
||||
// wait, hanging on it is not.
|
||||
TEST_F(SerialPacketLogTest, GivesUpWithinBudgetWhenHostWedgesMidLine) {
|
||||
primePort();
|
||||
FakePort port(64, 64);
|
||||
port.wedgeAfter(64); // host reads one FIFO-full, then stops
|
||||
uint8_t raw[200];
|
||||
memset(raw, 0xA5, sizeof(raw));
|
||||
|
||||
SerialLogLine<> line;
|
||||
line.printf("RAW: hex=");
|
||||
line.hex(raw, sizeof(raw)); // ~409 bytes: more than one FIFO-full
|
||||
|
||||
uint32_t before = millis();
|
||||
EXPECT_FALSE(line.flush(port));
|
||||
|
||||
uint32_t waited = millis() - before;
|
||||
EXPECT_GE(waited, (uint32_t)SERIAL_LOG_WRITE_BUDGET_MS);
|
||||
EXPECT_LE(waited, (uint32_t)SERIAL_LOG_WRITE_BUDGET_MS + 2) << "wait must be bounded";
|
||||
EXPECT_EQ((size_t)64, port.written().size());
|
||||
EXPECT_EQ(1u, serialLogDroppedCount());
|
||||
}
|
||||
|
||||
TEST_F(SerialPacketLogTest, ReportsTheGapOnceTheHostRecovers) {
|
||||
primePort();
|
||||
FakePort wedged;
|
||||
wedged.wedge();
|
||||
for (int i = 0; i < 3; i++) {
|
||||
SerialLogLine<> line;
|
||||
line.printf("RAW: hex=00");
|
||||
EXPECT_FALSE(line.flush(wedged));
|
||||
}
|
||||
ASSERT_EQ(3u, serialLogDroppedCount());
|
||||
|
||||
FakePort recovered(4096);
|
||||
SerialLogLine<> line;
|
||||
line.printf("RAW: hex=01");
|
||||
EXPECT_TRUE(line.flush(recovered));
|
||||
|
||||
EXPECT_EQ("DROP:3\r\nRAW: hex=01\r\n", recovered.written());
|
||||
EXPECT_EQ(0u, serialLogDroppedCount());
|
||||
}
|
||||
|
||||
// An unattached port reports no room exactly like a wedged one, so a host connecting to a
|
||||
// node that has been logging to nobody for hours must not be handed that whole tally.
|
||||
TEST_F(SerialPacketLogTest, DoesNotCountDropsBeforeAnyHostHasRead) {
|
||||
FakePort never_attached;
|
||||
never_attached.wedge();
|
||||
for (int i = 0; i < 5; i++) {
|
||||
SerialLogLine<> line;
|
||||
line.printf("RAW: hex=00");
|
||||
EXPECT_FALSE(line.flush(never_attached));
|
||||
}
|
||||
EXPECT_EQ(0u, serialLogDroppedCount());
|
||||
|
||||
FakePort attached(4096);
|
||||
SerialLogLine<> line;
|
||||
line.printf("RAW: hex=01");
|
||||
EXPECT_TRUE(line.flush(attached));
|
||||
EXPECT_EQ("RAW: hex=01\r\n", attached.written()) << "no DROP: preamble for lines nobody wanted";
|
||||
}
|
||||
|
||||
TEST_F(SerialPacketLogTest, OversizedLineIsTruncatedAndCounted) {
|
||||
primePort();
|
||||
FakePort port(4096);
|
||||
uint8_t raw[64];
|
||||
memset(raw, 0x5A, sizeof(raw));
|
||||
|
||||
SerialLogLine<32> line; // deliberately too small for the hex that follows
|
||||
line.printf("RAW: hex=");
|
||||
line.hex(raw, sizeof(raw));
|
||||
EXPECT_FALSE(line.flush(port));
|
||||
|
||||
EXPECT_LE(port.written().size(), (size_t)32);
|
||||
EXPECT_EQ('\n', port.written().back());
|
||||
EXPECT_EQ(1u, serialLogDroppedCount());
|
||||
}
|
||||
|
||||
// printf() overruns take the same path as hex() overruns.
|
||||
TEST_F(SerialPacketLogTest, OversizedPrintfIsTruncatedAndCounted) {
|
||||
primePort();
|
||||
FakePort port(4096);
|
||||
|
||||
SerialLogLine<16> line;
|
||||
line.printf("%s", "0123456789abcdefghij");
|
||||
EXPECT_FALSE(line.flush(port));
|
||||
|
||||
// No stray NUL from vsnprintf's terminator, and still newline-terminated.
|
||||
EXPECT_EQ("0123456789abc\r\n", port.written());
|
||||
EXPECT_EQ(1u, serialLogDroppedCount());
|
||||
}
|
||||
|
||||
} // namespace
|
||||
|
||||
int main(int argc, char** argv) {
|
||||
::testing::InitGoogleTest(&argc, argv);
|
||||
return RUN_ALL_TESTS();
|
||||
}
|
||||
@@ -209,11 +209,17 @@ lib_deps =
|
||||
; RX-tuning test build: identical to the observer above, plus per-packet RAW logging on
|
||||
; serial (snr_q/rssi/len/hex). Lets tools/rx-ab-runner.mjs take packet data straight off the
|
||||
; USB CLI on one host clock, with no MQTT/broker in the measurement path.
|
||||
;
|
||||
; The human-readable RX,/TX, lines stay off: the runner only parses RAW:, and emitting both
|
||||
; roughly doubles serial volume for no gain. The watchdog turns a wedged loop into a reboot
|
||||
; plus a boot banner (~30s) instead of an open-ended silent gap.
|
||||
[env:Station_G3_ESP32_repeater_observer_rxtest]
|
||||
extends = env:Station_G3_ESP32_repeater_observer_mqtt
|
||||
build_flags =
|
||||
${env:Station_G3_ESP32_repeater_observer_mqtt.build_flags}
|
||||
-D MESH_PACKET_LOGGING=1
|
||||
-D MESH_PACKET_LOGGING_TEXT=0
|
||||
-D WITH_TASK_WATCHDOG_SECS=30
|
||||
|
||||
[env:Station_G3_ESP32_room_server_observer_mqtt]
|
||||
extends = Station_G3_ESP32
|
||||
|
||||
Reference in New Issue
Block a user