diff --git a/examples/simple_repeater/MyMesh.cpp b/examples/simple_repeater/MyMesh.cpp index ef9ea501..29ed2b78 100644 --- a/examples/simple_repeater/MyMesh.cpp +++ b/examples/simple_repeater/MyMesh.cpp @@ -3,6 +3,9 @@ #include // for lroundf() #include // for qsort() #include +#if MESH_PACKET_LOGGING +#include +#endif #if defined(WITH_MQTT_NEIGHBORS) #include // 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 diff --git a/examples/simple_repeater/main.cpp b/examples/simple_repeater/main.cpp index 991fffb1..68455ea1 100644 --- a/examples/simple_repeater/main.cpp +++ b/examples/simple_repeater/main.cpp @@ -1,5 +1,7 @@ #include // needed for PlatformIO #include +#include +#include #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 } diff --git a/src/Dispatcher.cpp b/src/Dispatcher.cpp index 2a491a61..e87033d9 100644 --- a/src/Dispatcher.cpp +++ b/src/Dispatcher.cpp @@ -1,7 +1,8 @@ #include "Dispatcher.h" -#if MESH_PACKET_LOGGING +#if MESH_PACKET_LOGGING_TEXT #include + #include #endif #include @@ -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 } diff --git a/src/Dispatcher.h b/src/Dispatcher.h index 7edb7c7f..173f3a63 100644 --- a/src/Dispatcher.h +++ b/src/Dispatcher.h @@ -6,6 +6,13 @@ #include #include +// 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 { /** diff --git a/src/helpers/CommonCLI.cpp b/src/helpers/CommonCLI.cpp index ef5e976d..179a3587 100644 --- a/src/helpers/CommonCLI.cpp +++ b/src/helpers/CommonCLI.cpp @@ -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 "> (chip: )" 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()) { diff --git a/src/helpers/CommonCLI.h b/src/helpers/CommonCLI.h index fb287ffe..2520dd9f 100644 --- a/src/helpers/CommonCLI.h +++ b/src/helpers/CommonCLI.h @@ -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; diff --git a/src/helpers/SerialPacketLog.h b/src/helpers/SerialPacketLog.h new file mode 100644 index 00000000..f240300f --- /dev/null +++ b/src/helpers/SerialPacketLog.h @@ -0,0 +1,136 @@ +#pragma once + +#include +#include +#include +#include +#include +#include + +// 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 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 +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 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 +} diff --git a/src/helpers/TaskWatchdog.h b/src/helpers/TaskWatchdog.h new file mode 100644 index 00000000..82cb31d2 --- /dev/null +++ b/src/helpers/TaskWatchdog.h @@ -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=. 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 + +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 diff --git a/src/helpers/bridges/MQTTBridge.cpp b/src/helpers/bridges/MQTTBridge.cpp index 735999e9..9db863d9 100644 --- a/src/helpers/bridges/MQTTBridge.cpp +++ b/src/helpers/bridges/MQTTBridge.cpp @@ -5,6 +5,7 @@ #include "../MQTTReplyFormat.h" #include "../MQTTRuntimeBufferLifecycle.h" #include "../MQTTTopicRouter.h" +#include "../TaskWatchdog.h" #include "../TxtDataHelpers.h" #include #include @@ -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 diff --git a/test/test_serial_packet_log/test_serial_packet_log.cpp b/test/test_serial_packet_log/test_serial_packet_log.cpp new file mode 100644 index 00000000..3cbee1e3 --- /dev/null +++ b/test/test_serial_packet_log/test_serial_packet_log.cpp @@ -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 + +#include + +#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(); +} diff --git a/variants/station_g3_esp32/platformio.ini b/variants/station_g3_esp32/platformio.ini index a98a5007..68f9d12d 100644 --- a/variants/station_g3_esp32/platformio.ini +++ b/variants/station_g3_esp32/platformio.ini @@ -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