diff --git a/.github/workflows/run-unit-tests.yml b/.github/workflows/run-unit-tests.yml index ea239d73e..6a7f1259c 100644 --- a/.github/workflows/run-unit-tests.yml +++ b/.github/workflows/run-unit-tests.yml @@ -1046,6 +1046,7 @@ jobs: python3 -B test/test_usb_logging_watchdog.py python3 -B test/test_usb_watchdog_event.py python3 -B test/test_usb_logging_client_activity.py + python3 -B test/test_usb_packet_logging_quiet.py python3 -B test/test_usb_logging_watchdog_runtime.py python3 -B test/test_usb_logging_hwcdc_watchdog.py -v python3 -B test/test_usb_logging_hwcdc_presence.py -v diff --git a/docs/cli_commands.md b/docs/cli_commands.md index 858b9f2d4..a1a154caf 100644 --- a/docs/cli_commands.md +++ b/docs/cli_commands.md @@ -1694,6 +1694,26 @@ loading older preferences without a debug field. Updates retain an existing saved `usb.logging` choice. Older binaries without the new `usb.debug` command retain their previous behavior until upgraded. +On a shared USB console, an interactive text command pauses `RAW`, `RX`, and +`TX` packet log lines for five minutes. Each command restarts the timer; +logging then resumes automatically if its saved master is on. `get usb.logging` +still reports that saved setting. `set usb.logging on` or +`set logging.output usb|both` resumes packet logs immediately after a successful +save. No reboot is needed. + +The routine `stats-core`, `stats-radio`, and `stats-packets` polls do not start +or extend this pause. A separate logging USB port and explicit Companion +`usb.logging stream` mode also keep logging. The pause leaves command replies, +noise-floor sampling, saved history, LoRa telemetry, and direct WiFi MQTT +running. A collector reading USB packet logs misses those log copies during +the pause, including telemetry packets; this is not buffered capture. + +`meshcoretomqtt` polls these three stats commands every 300 seconds and +publishes `noise_floor` from the `stats-radio` reply in its MQTT status. These +polls keep working during the pause. Its startup identity queries do trigger +a five-minute packet-capture gap on a shared console, as do ordinary commands +sent through its remote serial feature. + For packet-only capture, use these separate text commands: ```text diff --git a/docs/usb_logging_watchdog.md b/docs/usb_logging_watchdog.md index 291abf888..e6449ffad 100644 --- a/docs/usb_logging_watchdog.md +++ b/docs/usb_logging_watchdog.md @@ -46,6 +46,14 @@ LoRa, management reports, and ordinary framed Companion traffic do not. No new heartbeat command is required. A cable, open TTY, DTR, or kernel USB ACK alone cannot qualify Auto. +Interactive text commands on a shared USB console pause packet logs for five +minutes after the last command. The three routine stats polls above keep +their replies and renew the lease without starting or extending this pause. +Dedicated logging ports and explicit Companion stream mode keep logging. +The pause does not disable measurements, LoRa telemetry, direct WiFi MQTT, +or the saved logging master. USB packet collectors miss log copies during +the pause. See [live USB logging](cli_commands.md#control-live-usb-logging). + `logger=1` requires the USB logging master, an observed host and reader, a fresh stats lease, and no physical TX stall. Any program polling those commands can qualify: this is not application identification or proof that packets were diff --git a/examples/companion_radio/MyMesh.cpp b/examples/companion_radio/MyMesh.cpp index 129792294..642922644 100644 --- a/examples/companion_radio/MyMesh.cpp +++ b/examples/companion_radio/MyMesh.cpp @@ -820,7 +820,7 @@ const char* MyMesh::getLogDateTime() { void MyMesh::logRxRaw(float snr, float rssi, const uint8_t raw[], int len) { #if MESH_PACKET_LOGGING - if (mesh::isUsbLoggingEnabled()) { + if (mesh::isUsbPacketLoggingAllowed()) { mesh::SerialLogLine<> line; #if MESH_PACKET_LOGGING_COMPACT line.printf("R"); @@ -4380,22 +4380,25 @@ bool MyMesh::handleLocalControlCommand(const char* command, char* reply, mesh::cli::formatError(reply, reply_size, "USB logging changed for this boot but save failed"); } else if (!mesh::saveUsbLoggingBootPreference(enabled)) { mesh::cli::formatError(reply, reply_size, "setting saved, but next-boot USB interface state could not be saved"); - } else if (mesh::usbLoggingInterfaceRestartRequired() - || (enabled && packet_stream != mesh::isUsbLoggingPacketStream())) { - if (reboot_if_needed) { - snprintf(reply, reply_size, - "OK - USB logging %s (saved); rebooting to change USB interfaces", - enabled ? (packet_stream ? "stream" : "on") : "off"); - _scheduled_reboot_at = futureMillis(1000); - if (_scheduled_reboot_at == 0) _scheduled_reboot_at = 1; - } else { - snprintf(reply, reply_size, - "OK - USB logging %s (saved); reboot required to change USB interfaces", - enabled ? (packet_stream ? "stream" : "on") : "off"); - } } else { - snprintf(reply, reply_size, "OK - USB logging %s (saved)", - enabled ? (packet_stream ? "stream" : "on") : "off"); + if (enabled) mesh::resumeUsbPacketLogging(); + if (mesh::usbLoggingInterfaceRestartRequired() + || (enabled && packet_stream != mesh::isUsbLoggingPacketStream())) { + if (reboot_if_needed) { + snprintf(reply, reply_size, + "OK - USB logging %s (saved); rebooting to change USB interfaces", + enabled ? (packet_stream ? "stream" : "on") : "off"); + _scheduled_reboot_at = futureMillis(1000); + if (_scheduled_reboot_at == 0) _scheduled_reboot_at = 1; + } else { + snprintf(reply, reply_size, + "OK - USB logging %s (saved); reboot required to change USB interfaces", + enabled ? (packet_stream ? "stream" : "on") : "off"); + } + } else { + snprintf(reply, reply_size, "OK - USB logging %s (saved)", + enabled ? (packet_stream ? "stream" : "on") : "off"); + } } } return true; @@ -4931,6 +4934,7 @@ bool MyMesh::handleLocalControlCommand(const char* command, char* reply, if (!savePrefs() || !mesh::saveUsbLoggingBootPreference(usb)) { mesh::cli::formatError(reply, reply_size, "logging output changed but USB setting could not be saved"); } else { + if (usb) mesh::resumeUsbPacketLogging(); // USB ownership changes can clear the terminal's input buffer while // this command is executing. Use parsed values, not that borrowed text. snprintf(reply, reply_size, "OK - logging.output %s (saved)", @@ -11403,6 +11407,7 @@ void MyMesh::checkCLIRescueCmd() { complete_line: { + if (strlen(cli_command) == len) mesh::noteUsbConsoleCommand(cli_command); reply_buf[0] = 0; #if COMPANION_FEATURE_READER if (mesh::morseTimingActive(_radio) && isCompanionReaderRequest(cli_command)) { diff --git a/examples/companion_radio/main.cpp b/examples/companion_radio/main.cpp index e0b558848..fe222c243 100644 --- a/examples/companion_radio/main.cpp +++ b/examples/companion_radio/main.cpp @@ -1408,6 +1408,7 @@ static void serviceUsbTerminal() { #endif // NUL-containing lines were discarded before reaching this point. On // dual CDC hardware only CDC1 is the logging-reader endpoint. + mesh::noteUsbConsoleCommand(usb_terminal_line); if (!mesh::hasDedicatedUsbLoggingPort()) mesh::noteUsbLoggingStatsCommand(usb_terminal_line); the_mesh.handleTerminalCommand(usb_terminal_line); diff --git a/examples/simple_repeater/MyMesh.cpp b/examples/simple_repeater/MyMesh.cpp index 4fed902fb..681e431f3 100644 --- a/examples/simple_repeater/MyMesh.cpp +++ b/examples/simple_repeater/MyMesh.cpp @@ -1261,7 +1261,7 @@ bool MyMesh::allowTransportPacket(const mesh::Packet* packet, uint8_t context) { void MyMesh::logRxRaw(float snr, float rssi, const uint8_t raw[], int len) { #if MESH_PACKET_LOGGING - if (mesh::isUsbLoggingEnabled()) { + if (mesh::isUsbPacketLoggingAllowed()) { #if MESH_PACKET_LOGGING_COMPACT mesh::serialLogCompactPacket(mesh::usbLoggingPort(), 'R', raw, len); #else diff --git a/examples/simple_repeater/main.cpp b/examples/simple_repeater/main.cpp index f089cd103..45ec9755a 100644 --- a/examples/simple_repeater/main.cpp +++ b/examples/simple_repeater/main.cpp @@ -626,8 +626,10 @@ static void __attribute__((noinline)) serviceCommandInterfaces() { console.print('\n'); char reply[160]; reply[0] = 0; - if (strlen(command) == static_cast(len)) + if (strlen(command) == static_cast(len)) { + mesh::noteUsbConsoleCommand(command); mesh::noteUsbLoggingStatsCommand(command); + } #if defined(MESH_SOAK_DIAGNOSTICS) if (mesh::hil::handleSoakCommand(command, reply, sizeof(reply))) { console.print(" -> "); diff --git a/examples/simple_room_server/MyMesh.cpp b/examples/simple_room_server/MyMesh.cpp index 4721bd129..cc75ce521 100644 --- a/examples/simple_room_server/MyMesh.cpp +++ b/examples/simple_room_server/MyMesh.cpp @@ -1458,7 +1458,7 @@ bool MyMesh::allowTransportPacket(const mesh::Packet* packet, uint8_t context) { void MyMesh::logRxRaw(float snr, float rssi, const uint8_t raw[], int len) { #if MESH_PACKET_LOGGING - if (mesh::isUsbLoggingEnabled()) { + if (mesh::isUsbPacketLoggingAllowed()) { mesh::SerialLogLine<> line; line.printf("%s RAW: ", getLogDateTime()); line.hex(raw, len); diff --git a/examples/simple_room_server/main.cpp b/examples/simple_room_server/main.cpp index a6498e285..10d89c391 100644 --- a/examples/simple_room_server/main.cpp +++ b/examples/simple_room_server/main.cpp @@ -413,8 +413,10 @@ void loop() { char reply[160]; reply[0] = 0; if (len < static_cast(sizeof(command) - 1) - && strlen(command) == static_cast(len - 1)) + && strlen(command) == static_cast(len - 1)) { + mesh::noteUsbConsoleCommand(command); mesh::noteUsbLoggingStatsCommand(command); + } #ifdef ETHERNET_ENABLED if (!ethernet_handle_command(command, reply)) { the_mesh.handleUsbCommand(command, reply); diff --git a/examples/simple_sensor/main.cpp b/examples/simple_sensor/main.cpp index 0a98f0f3c..17a806895 100644 --- a/examples/simple_sensor/main.cpp +++ b/examples/simple_sensor/main.cpp @@ -396,8 +396,10 @@ void loop() { char reply[160]; reply[0] = 0; if (len < static_cast(sizeof(command) - 1) - && strlen(command) == static_cast(len - 1)) + && strlen(command) == static_cast(len - 1)) { + mesh::noteUsbConsoleCommand(command); mesh::noteUsbLoggingStatsCommand(command); + } the_mesh.handleCommand(0, command, reply); // NOTE: there is no sender_timestamp via serial! if (reply[0]) { console.print(" -> "); diff --git a/src/Dispatcher.cpp b/src/Dispatcher.cpp index 1fda9586c..a283b334a 100644 --- a/src/Dispatcher.cpp +++ b/src/Dispatcher.cpp @@ -234,7 +234,7 @@ bool Dispatcher::startOutboundTransmit() { outbound_expiry = futureMillis(max_airtime); #if MESH_PACKET_LOGGING - if (isUsbLoggingEnabled()) { + if (isUsbPacketLoggingAllowed()) { #if MESH_PACKET_LOGGING_COMPACT serialLogCompactPacket(usbLoggingPort(), 'T', raw, len); #else @@ -1164,7 +1164,7 @@ void Dispatcher::checkRecv() { } if (pkt) { #if MESH_PACKET_LOGGING && !MESH_PACKET_LOGGING_COMPACT - if (isUsbLoggingEnabled()) { + if (isUsbPacketLoggingAllowed()) { logPacketLine("RX", pkt, pkt->getRawLength(), true, score, air_time); } #endif diff --git a/src/helpers/CommonCLI.cpp b/src/helpers/CommonCLI.cpp index aab50a352..7f925a1ab 100644 --- a/src/helpers/CommonCLI.cpp +++ b/src/helpers/CommonCLI.cpp @@ -4453,6 +4453,7 @@ void CommonCLI::handleSetCmd(uint32_t sender_timestamp, char* command, char* rep } // Commit before changing the stream's live protocol ownership. mesh::setUsbLoggingEnabled(enabled); + if (enabled) mesh::resumeUsbPacketLogging(); snprintf(reply, 160, "OK - USB logging %s (saved)", enabled ? "on" : "off"); } else { mesh::cli::formatError(reply, 160, "usage set usb.logging on|off"); @@ -4503,6 +4504,7 @@ void CommonCLI::handleSetCmd(uint32_t sender_timestamp, char* command, char* rep return; } mesh::setUsbLoggingEnabled(usb_enabled); + if (usb_enabled) mesh::resumeUsbPacketLogging(); const bool applied = wifi_enabled ? _callbacks->setMqttBridgeState(true) : _callbacks->requestMqttBridgeStop(); if (!applied) { diff --git a/src/helpers/UsbLogging.cpp b/src/helpers/UsbLogging.cpp index 50d2d3850..d13f1fcf1 100644 --- a/src/helpers/UsbLogging.cpp +++ b/src/helpers/UsbLogging.cpp @@ -94,6 +94,9 @@ static std::atomic usb_logging_enabled{true}; #endif static std::atomic usb_logging_preference_known{false}; static std::atomic usb_debug_enabled{false}; +#if MESH_USB_LOGGING_AVAILABLE +static std::atomic usb_packet_logging_quiet_until{0}; +#endif #if MESH_ENABLE_HOST_KISS static std::atomic usb_binary_stream_owned{false}; static std::atomic usb_text_writers{0}; @@ -1294,6 +1297,36 @@ bool isUsbLoggingEnabled() { return usb_logging_enabled.load(std::memory_order_relaxed); } +#if MESH_USB_LOGGING_AVAILABLE +void noteUsbConsoleCommand(const char* command) { + if (command == nullptr || hasDedicatedUsbLoggingPort() || isUsbLoggingPacketStream()) return; + while (*command == ' ' || *command == '\t' || *command == '\r' || *command == '\n') ++command; + if (*command == 0 || isUsbLoggingStatsCommand(command)) return; + for (const unsigned char* p = reinterpret_cast(command); *p; ++p) { + if ((*p < 32 && *p != '\t') || *p >= 127) return; + } + uint32_t deadline = uint32_t(millis()) + 300000UL; + if (deadline == 0) deadline = 1; + usb_packet_logging_quiet_until.store(deadline, std::memory_order_relaxed); +} + +void resumeUsbPacketLogging() { + usb_packet_logging_quiet_until.store(0, std::memory_order_relaxed); +} + +bool isUsbPacketLoggingAllowed() { + uint32_t deadline = usb_packet_logging_quiet_until.load(std::memory_order_relaxed); + bool quiet = deadline != 0; + if (quiet && int32_t(uint32_t(millis()) - deadline) >= 0) { + // Do not clear a newer command's pause if it raced this expiry sample. + quiet = !usb_packet_logging_quiet_until.compare_exchange_strong( + deadline, 0, std::memory_order_relaxed) && deadline != 0; + } + return isUsbLoggingEnabled() + && (hasDedicatedUsbLoggingPort() || isUsbLoggingPacketStream() || !quiet); +} +#endif + bool isUsbDebugEnabled() { return usb_debug_enabled.load(std::memory_order_relaxed); } diff --git a/src/helpers/UsbLogging.h b/src/helpers/UsbLogging.h index 7f05c2309..4e514d15d 100644 --- a/src/helpers/UsbLogging.h +++ b/src/helpers/UsbLogging.h @@ -92,6 +92,19 @@ inline size_t nextUsbLoggingIdentityOffset(size_t current_offset, // protect framed traffic and restores its saved choice after preferences load. bool isUsbLoggingEnabled(); void setUsbLoggingEnabled(bool enabled); +#if MESH_USB_LOGGING_AVAILABLE +// Human console commands pause packet records for five minutes without +// changing the saved logging setting, functional replies, or debug output. +// Dedicated logging endpoints, explicit packet streams, and stats polls keep +// their continuous capture contract. Explicit logging-on commands may resume. +void noteUsbConsoleCommand(const char* command); +void resumeUsbPacketLogging(); +bool isUsbPacketLoggingAllowed(); +#else +inline void noteUsbConsoleCommand(const char*) {} +inline void resumeUsbPacketLogging() {} +inline bool isUsbPacketLoggingAllowed() { return false; } +#endif // Verbose diagnostics are opt-in and persisted by the role preferences. // The requested setting survives switching the master USB output gate off. bool isUsbDebugEnabled(); diff --git a/test/fixtures/companion_scheduled_reboot/test.cpp b/test/fixtures/companion_scheduled_reboot/test.cpp index b769a1e55..8286876e2 100644 --- a/test/fixtures/companion_scheduled_reboot/test.cpp +++ b/test/fixtures/companion_scheduled_reboot/test.cpp @@ -30,6 +30,7 @@ struct Stream { namespace mesh { bool morseTimingActive(const void*) { return morse_active; } bool saveUsbLoggingBootPreference(bool) { return boot_save_ok; } +void resumeUsbPacketLogging() {} bool usbLoggingInterfaceRestartRequired() { return true; } bool isUsbLoggingPacketStream() { return false; } } diff --git a/test/test_common_cli_logging_transaction.py b/test/test_common_cli_logging_transaction.py index 53fe3b26b..fffe4a575 100644 --- a/test/test_common_cli_logging_transaction.py +++ b/test/test_common_cli_logging_transaction.py @@ -18,8 +18,10 @@ HARNESS = r''' struct Prefs { uint8_t usb_logging_enabled = 0, bridge_enabled = 0; }; static bool live_usb = false; static unsigned usb_calls = 0; +static unsigned resume_calls = 0; namespace mesh { void setUsbLoggingEnabled(bool value) { live_usb = value; ++usb_calls; } +void resumeUsbPacketLogging() { ++resume_calls; } } struct Callbacks { bool live_wifi = false, apply_ok = true, stopping = false, pending = false; @@ -50,6 +52,7 @@ static void check(const char* command, bool usb, bool wifi, bool failed) { live_usb = !usb; cli.callbacks.live_wifi = !wifi; usb_calls = 0; + resume_calls = 0; cli.save_ok = !failed; char reply[160]{}; cli.set(command, reply); @@ -58,6 +61,7 @@ static void check(const char* command, bool usb, bool wifi, bool failed) { assert(cli.persisted.usb_logging_enabled == (failed ? !usb : usb)); assert(live_usb == (failed ? !usb : usb)); assert(usb_calls == (failed ? 0u : 1u)); + assert(resume_calls == (!failed && usb ? 1u : 0u)); assert(strstr(reply, failed ? "unconfirmed" : "(saved)")); if (failed) assert(strstr(reply, "reboot may differ")); if (strncmp(command, "logging.output", 14) == 0) { @@ -88,9 +92,11 @@ int main() { cli.set("logging.output invalid", reply); assert(cli.saves == 0 && strstr(reply, "Error:")); cli.callbacks.apply_ok = false; + resume_calls = 0; cli.set("logging.output both", reply); assert(cli.persisted.usb_logging_enabled && cli.persisted.bridge_enabled); assert(live_usb && !cli.callbacks.live_wifi); + assert(resume_calls == 1); assert(strstr(reply, "saved, but MQTT runtime change failed")); // A restart during cleanup saves intent without interrupting the old worker. cli.callbacks.stopping = true; @@ -120,7 +126,10 @@ class LoggingTransactionTest(unittest.TestCase): #include "helpers/CLICommandUtils.h" static char input[64]; namespace CompanionMqttSetupPortal { static bool saveEnabled(bool) { return true; } } -namespace mesh { static bool saveUsbLoggingBootPreference(bool) { return true; } } +namespace mesh { +static bool saveUsbLoggingBootPreference(bool) { return true; } +inline void resumeUsbPacketLogging() {} +} struct Mesh { bool _mqtt_enabled = true; struct { unsigned usb_logging_enabled = 1; } _prefs; diff --git a/test/test_common_usb_debug.py b/test/test_common_usb_debug.py index b4b6a8b5e..0bd68c5f0 100644 --- a/test/test_common_usb_debug.py +++ b/test/test_common_usb_debug.py @@ -68,6 +68,7 @@ void setUsbLoggingEnabled(bool enabled) { } void setUsbDebugEnabled(bool enabled) { usb_debug = enabled; ++debug_updates; } bool isUsbLoggingEnabled() { return usb_logging; } +void resumeUsbPacketLogging() {} bool isUsbDebugEnabled() { return usb_debug; } bool isUsbDebugLoggingEnabled() { return usb_logging && usb_debug; } } diff --git a/test/test_companion_packet_stream.py b/test/test_companion_packet_stream.py index 81b774547..b18bc3f77 100644 --- a/test/test_companion_packet_stream.py +++ b/test/test_companion_packet_stream.py @@ -44,6 +44,8 @@ void setPlatformDebugOutputEnabled(bool){} void setUsbDebugEnabled(bool){} void setUsbLoggingEnabled(bool enabled){logging=enabled;usb_logging_preference_known=true;} bool saveUsbLoggingBootPreference(bool){return true;} +unsigned packet_logging_resumes=0; +void resumeUsbPacketLogging(){++packet_logging_resumes;} @USB_FUNCTIONS@ void freshBoot(){ dedicated_usb_logging_port_started=false;dedicated_usb_logging_port_configured=false; @@ -121,11 +123,15 @@ int main(){ for(const char* invalid : {"set usb.logging stream extra","set usb.logging STREAM", "set usb.logging stream ","set usb.logging stream reboot ","set usb.loggingstream"}){ const auto before=node.store.fs.files["/new_prefs"]; + const unsigned resumes=mesh::packet_logging_resumes; const bool handled=node.command(invalid,reply,sizeof(reply)); + assert(mesh::packet_logging_resumes==resumes); if(handled)assert(strstr(reply,"Error:")); assert(node.store.fs.files["/new_prefs"]==before&&node._prefs.usb_logging_enabled==1); } + const unsigned resumes=mesh::packet_logging_resumes; assert(node.command("set usb.logging stream",reply,sizeof(reply))); + assert(mesh::packet_logging_resumes==resumes+1); assert(node._prefs.usb_logging_enabled==2&&node.store.fs.files["/new_prefs"][158]==2); assert(strstr(reply,"reboot required"));assert(node._scheduled_reboot_at==0); assert(!mesh::isUsbLoggingPacketStream()); // Saved choice cannot flip a live descriptor/route. @@ -149,7 +155,12 @@ int main(){ bootMode(node,1);node._scheduled_reboot_at=0; assert(node.command("set usb.logging stream",reply,sizeof(reply))); node.store.fs.fail_write=true; + const unsigned before_failed_save=mesh::packet_logging_resumes; assert(node.command("set usb.logging off",reply,sizeof(reply))); + for(const char* failed : {"set usb.logging on","set usb.logging stream"}) { + assert(node.command(failed,reply,sizeof(reply)) && strstr(reply,"save failed")); + assert(mesh::packet_logging_resumes==before_failed_save); + } assert(strstr(reply,"save failed")&&node.store.fs.files["/new_prefs"][158]==2); assert(!mesh::isUsbLoggingPacketStream()); char guarded[17];memset(guarded,'X',sizeof(guarded)); diff --git a/test/test_companion_usb_input.py b/test/test_companion_usb_input.py index 863fec0a8..03f0cfa81 100644 --- a/test/test_companion_usb_input.py +++ b/test/test_companion_usb_input.py @@ -90,8 +90,9 @@ struct OtaContext { ArduinoSerialInterface usb_serial_interface; static Stream& usbTerminalOutput() { return input; } static bool connected=true, logging=false, dedicated=false; -static std::vector stats_commands; +static std::vector stats_commands, console_commands; namespace mesh { +void noteUsbConsoleCommand(const char* command) { console_commands.emplace_back(command); } bool isUsbLoggingEnabled() { return logging; } bool hasDedicatedUsbLoggingPort() { return dedicated; } void noteUsbLoggingStatsCommand(const char* command) { @@ -154,7 +155,7 @@ static void drainUsbTerminalOutputBeforeProtocolSwitch() {} @FUNCTIONS@ static void reset() { input=Input(); the_mesh=Mesh(); connected=true; logging=dedicated=false; - stats_commands.clear(); + stats_commands.clear(); console_commands.clear(); mesh::ota::OtaContext::serialFolderSource().resetSessionState(); usb_serial_interface=ArduinoSerialInterface(); usb_serial_interface.begin(input,USB_TERMINAL_START_TOKEN,USB_MOTA_START_TOKEN); @@ -192,18 +193,20 @@ int main() { assert(input.available()==5 && input.peek()=='<'); assert(input.output.empty() && the_mesh.banners==0); finishProbe(); + assert(console_commands.empty()); } // Empty Enter reveals the silent terminal without fabricating a command. for(const char* leading : {"\r","\n","\r\n"}) { reset(); input.push(leading); serviceUsbTerminal(); assert(the_mesh.terminal && !the_mesh.waiting && the_mesh.banners==1); assert(!usb_binary_startup_probe.isActive() && input.available()==0); - assert(the_mesh.commands.empty()); + assert(the_mesh.commands.empty() && console_commands.empty()); serviceUsbTerminal(); assert(the_mesh.banners==1); } reset(); input.push("\r\nget name\r\n"); serviceUsbTerminal(); assert(the_mesh.banners==1 && the_mesh.commands.size()==1); assert(the_mesh.commands[0]=="get name" && the_mesh.terminal); + assert(console_commands==the_mesh.commands); // Reaching an empty prompt through an edit also leaves the frame untouched. reset(); input.push("x\b"); input.frame(); serviceUsbTerminal(); assert(usb_binary_startup_probe.isActive() && input.available()==5); @@ -311,7 +314,7 @@ int main() { serviceUsbTerminal(); assert(!usb_mota_mode && the_mesh.attaches==0 && the_mesh.detaches==0); assert(the_mesh.commands.size()==1 && the_mesh.commands[0]=="get name"); - assert(stats_commands==the_mesh.commands); + assert(stats_commands==the_mesh.commands && console_commands==the_mesh.commands); const auto error=input.output.find("ERROR: invalid command"); assert(error!=std::string::npos); assert(input.output.find("ERROR: invalid command",error+1)==std::string::npos); @@ -330,7 +333,7 @@ int main() { assert(oversized_setter.size()==610); reset(); input.hwcdcBurst(oversized_setter,256); serviceUsbTerminal(); assert(input.rx_dropped==354 && input.output.size()==256+6); // Silent banner is revealed. - assert(the_mesh.commands.empty() && usb_terminal_line_len==256); + assert(the_mesh.commands.empty() && usb_terminal_line_len==256 && console_commands.empty()); assert(!usb_terminal_discard_line && input.output.find("ERROR")==std::string::npos); input.push("\r"); serviceUsbTerminal(); assert(the_mesh.commands==std::vector{oversized_setter.substr(0,256)}); diff --git a/test/test_companion_usb_logging.py b/test/test_companion_usb_logging.py index 0b50eaf38..2db641863 100644 --- a/test/test_companion_usb_logging.py +++ b/test/test_companion_usb_logging.py @@ -199,7 +199,7 @@ struct Port : Stream { } log_port; namespace mesh { bool enabled=true,debug_enabled=false; -bool isUsbLoggingEnabled(){return enabled;} +bool isUsbPacketLoggingAllowed(){return enabled;} Port& usbLoggingPort(){return log_port;} } struct Transport { diff --git a/test/test_companion_usb_logging_reply.py b/test/test_companion_usb_logging_reply.py index 23cc90853..0d2981710 100644 --- a/test/test_companion_usb_logging_reply.py +++ b/test/test_companion_usb_logging_reply.py @@ -84,6 +84,7 @@ void setUsbLoggingEnabled(bool value) { logging=value; } void discardUsbTerminalOutput() {} Stream& usbCompanionPort() { return stream; } bool saveUsbLoggingBootPreference(bool) { return true; } +void resumeUsbPacketLogging() {} bool usbLoggingInterfaceRestartRequired() { return false; } bool isUsbLoggingPacketStream() { return false; } } diff --git a/test/test_mini_repeater_logging.py b/test/test_mini_repeater_logging.py index c3ec7cf80..ea31f2d2f 100644 --- a/test/test_mini_repeater_logging.py +++ b/test/test_mini_repeater_logging.py @@ -66,7 +66,7 @@ struct Port : Stream { namespace mesh { bool logging_enabled = true; -bool isUsbLoggingEnabled() { return logging_enabled; } +bool isUsbPacketLoggingAllowed() { return logging_enabled; } Stream& usbLoggingPort() { return log_port; } void Utils::toHex(char* destination, const uint8_t* source, size_t size) { const char* digits = "0123456789ABCDEF"; diff --git a/test/test_usb_packet_logging_quiet.py b/test/test_usb_packet_logging_quiet.py new file mode 100644 index 000000000..c98036766 --- /dev/null +++ b/test/test_usb_packet_logging_quiet.py @@ -0,0 +1,201 @@ +"""Execute packet-only quiet periods with the real USB facade and RAW emitter.""" +from pathlib import Path +import os +import subprocess +import sys +import tempfile +import unittest + +from test_radio_receive_contract import method + +ROOT = Path(__file__).resolve().parents[1] +FIXTURE = ROOT / "test/fixtures/nrf52_usb_console" +SANITIZERS = (["-fsanitize=address,undefined", "-fno-sanitize-recover=all", + "-fno-pie", "-no-pie"] if sys.platform.startswith("linux") else []) + +CASES = r''' +#include +#include +@PUSH_CODE@ +struct PacketTransport { + unsigned frames=0; + bool isConnected() const {return true;} + size_t writeFrame(const uint8_t*,size_t size){++frames;return size;} +}; +struct MyMesh { + PacketTransport transport; + PacketTransport* _serial=&transport; + uint8_t out_frame[MAX_FRAME_SIZE]={}; + const char* getLogDateTime(){return "stamp";} + void logRxRaw(float,float,const uint8_t*,int); +}; +@RAW_EMITTER@ +static void timerCases() { + mesh::setUsbLoggingEnabled(true);mesh::resumeUsbPacketLogging(); + mesh::configureUsbLoggingPacketStream(false);g_mock_millis=0; + for(const char* ignored:std::initializer_list{nullptr,""," \t\r\n","stats-core"," \tstats-radio\t ","stats-packets", + "\x01" "get name","get\x7f","\xff" "get name","get name\n","stats-core\r","get\rname"}) { + mesh::noteUsbConsoleCommand(ignored);assert(mesh::isUsbPacketLoggingAllowed()); + } + for(const char* human:{"get name","stats-core extra","stats-radiox","stats-packets 1"}) { + mesh::noteUsbConsoleCommand(human);assert(!mesh::isUsbPacketLoggingAllowed()); + mesh::resumeUsbPacketLogging(); + } + mesh::noteUsbConsoleCommand("get name"); + assert(mesh::isUsbLoggingEnabled()&&!mesh::isUsbPacketLoggingAllowed()); + g_mock_millis=299999;assert(!mesh::isUsbPacketLoggingAllowed()); + ++g_mock_millis;assert(mesh::isUsbPacketLoggingAllowed()); + g_mock_millis+=0x80000000U;assert(mesh::isUsbPacketLoggingAllowed()); // Expiry latches. + g_mock_millis=100;mesh::noteUsbConsoleCommand("get radio"); + g_mock_millis+=299000;mesh::noteUsbConsoleCommand("get name"); + g_mock_millis+=1000;assert(!mesh::isUsbPacketLoggingAllowed()); + g_mock_millis+=298999;assert(!mesh::isUsbPacketLoggingAllowed()); + ++g_mock_millis;assert(mesh::isUsbPacketLoggingAllowed()); + g_mock_millis=UINT32_MAX-100000;mesh::noteUsbConsoleCommand("get name"); + g_mock_millis+=299999;assert(!mesh::isUsbPacketLoggingAllowed()); + ++g_mock_millis;assert(mesh::isUsbPacketLoggingAllowed()); + // Zero is the inactive sentinel; its single-tick coercion must stay bounded. + g_mock_millis=uint32_t(0U-300000U);mesh::noteUsbConsoleCommand("get name"); + g_mock_millis=0;assert(!mesh::isUsbPacketLoggingAllowed()); + g_mock_millis=1;assert(mesh::isUsbPacketLoggingAllowed()); + g_mock_millis=500;mesh::noteUsbConsoleCommand("get name"); + mesh::setUsbLoggingEnabled(true);assert(!mesh::isUsbPacketLoggingAllowed()); + mesh::setUsbLoggingEnabled(false);g_mock_millis+=300000; + assert(!mesh::isUsbPacketLoggingAllowed()&&!mesh::isUsbLoggingEnabled()); + g_mock_millis+=0x80000000U;mesh::setUsbLoggingEnabled(true); + assert(mesh::isUsbPacketLoggingAllowed()); // Reapply never resurrects an expired pause. + mesh::noteUsbConsoleCommand("get name");mesh::resumeUsbPacketLogging(); + assert(mesh::isUsbPacketLoggingAllowed()); + mesh::setUsbLoggingEnabled(false);mesh::resumeUsbPacketLogging(); + assert(!mesh::isUsbPacketLoggingAllowed()&&!mesh::isUsbLoggingEnabled()); + mesh::setUsbLoggingEnabled(true);mesh::configureUsbLoggingPacketStream(true); + mesh::noteUsbConsoleCommand("get name");assert(mesh::isUsbPacketLoggingAllowed()); + mesh::configureUsbLoggingPacketStream(false);assert(mesh::isUsbPacketLoggingAllowed()); + std::puts("PASS: packet quiet timers, reset, wrap, polls, stream and saved master"); +} +static void outputCases() { + mesh::setUsbLoggingEnabled(true);mesh::setUsbDebugEnabled(true); + mesh::resumeUsbPacketLogging();tud_cdc_line_state_cb(0,true,false);service(); + MyMesh node;const uint8_t raw[]={0x00,0xab,0xff}; + auto& console=mesh::usbConsolePort(); + const std::string reply="-> name: Companion\r\n"; + assert(console.write(reinterpret_cast(reply.data()),reply.size())==reply.size()); + mesh::noteUsbConsoleCommand("get name"); + node.logRxRaw(2.5f,-92,raw,sizeof(raw));drain(); + if(host!=reply||node.transport.frames!=1) + std::fprintf(stderr,"quiet host=[%s] bytes=%zu frames=%u allowed=%d\n",host.c_str(),host.size(),node.transport.frames,mesh::isUsbPacketLoggingAllowed()); + assert(host==reply&&node.transport.frames==1); + assert(mesh::isUsbLoggingEnabled()&&mesh::isUsbDebugLoggingEnabled()); + assert(mesh::serialLogDroppedCount()==0);host.clear(); + mesh::resumeUsbPacketLogging(); + uint8_t large[160];std::fill(large,large+sizeof(large),0xa5); + during_write=[] {mesh::noteUsbConsoleCommand("get radio");}; + node.logRxRaw(2.5f,-92,large,sizeof(large));drain(); + std::string hex;for(unsigned i=0;i(reply.data()),reply.size())==reply.size()); + drain();assert(host==reply&&host.find('\x1b')==std::string::npos); + assert(mesh::serialLogDroppedCount()==0);host.clear(); + mesh::resumeUsbPacketLogging();node.logRxRaw(2.5f,-92,raw,sizeof(raw));drain(); +#if MESH_PACKET_LOGGING_COMPACT + assert(host=="R00ABFF\n"); +#else + assert(host=="stamp RAW: 00ABFF\r\n"); +#endif + std::puts("PASS: quiet RAW records preserve replies and complete in-progress records"); +} +int main(int argc,char**) {if(argc==1)timerCases();else outputCases();} +''' + +CORE_CASE = r''' +#include +#include +#include +#include +namespace mesh { +static std::atomic usb_logging_enabled{true}; +static std::atomic usb_packet_logging_quiet_until{0}; +bool dedicated=false,stream=false; +bool hasDedicatedUsbLoggingPort(){return dedicated;} +bool isUsbLoggingPacketStream(){return stream;} +@METHODS@ +} +int main() { + mesh::noteUsbConsoleCommand("get name");assert(!mesh::isUsbPacketLoggingAllowed()); + mesh::dedicated=true;assert(mesh::isUsbPacketLoggingAllowed()); + mesh::resumeUsbPacketLogging();mesh::noteUsbConsoleCommand("get name"); + mesh::dedicated=false;assert(mesh::isUsbPacketLoggingAllowed()); + mesh::dedicated=true;mesh::usb_logging_enabled=false; + assert(!mesh::isUsbPacketLoggingAllowed()); +} +''' + + +class UsbPacketLoggingQuietTests(unittest.TestCase): + def compile(self, work, name, text, flags=(), sources=()): + source = work / (name + ".cpp") + source.write_text(text) + binary = work / (name + ".exe") + built = subprocess.run([os.environ.get("CXX", "g++"), "-std=c++17", "-Wall", "-Wextra", + "-Werror", *SANITIZERS, "-DARDUINO", *flags, + "-I" + str(FIXTURE / "mocks"), "-I" + str(ROOT / "src"), + str(source), *[str(path) for path in sources], "-o", str(binary)], + capture_output=True, text=True, timeout=60) + self.assertEqual(built.returncode, 0, built.stdout + built.stderr) + return binary + + def test_actual_usb_facade_timers_and_raw_emitter_output(self): + prefix = (FIXTURE / "test_console.cpp").read_text().split("int main()")[0] + source = (ROOT / "examples/companion_radio/MyMesh.cpp").read_text() + cases = CASES.replace("@PUSH_CODE@", next(line for line in source.splitlines() + if line.startswith("#define PUSH_CODE_LOG_RX_DATA"))) + cases = cases.replace("@RAW_EMITTER@", method(source, "void MyMesh::logRxRaw(")) + with tempfile.TemporaryDirectory(prefix="meshcore-packet-quiet-") as directory: + work = Path(directory) + for compact in (0, 1): + with self.subTest(compact=compact): + binary = self.compile(work, "quiet" + str(compact), prefix + cases, + ["-DNRF52_PLATFORM", "-DUSE_TINYUSB", "-DENABLE_USB_INTERFACE", + "-DMESH_DEBUG=1", "-DMESH_PACKET_LOGGING=1", "-DMESH_PACKET_LOGGING_COMPACT=" + str(compact)], + [ROOT / "src/helpers" / name for name in ( + "UsbLogging.cpp", "UsbLoggingClientActivity.cpp", "UsbLoggingLineStateOverride.cpp")]) + for arguments in ([], ["output"]): + ran = subprocess.run([str(binary), *arguments], capture_output=True, text=True, timeout=20) + self.assertEqual(ran.returncode, 0, ran.stdout + ran.stderr) + self.assertIn("PASS:", ran.stdout) + + def test_actual_core_dedicated_endpoint_bypasses_automatic_pause(self): + source = (ROOT / "src/helpers/UsbLogging.cpp").read_text() + methods = "\n".join(method(source, signature) for signature in ( + "bool isUsbLoggingEnabled(", "void noteUsbConsoleCommand(", + "void resumeUsbPacketLogging(", "bool isUsbPacketLoggingAllowed(")) + with tempfile.TemporaryDirectory(prefix="meshcore-packet-dedicated-") as directory: + binary = self.compile(Path(directory), "dedicated", CORE_CASE.replace("@METHODS@", methods), ["-DMESH_DEBUG=1"]) + ran = subprocess.run([str(binary)], capture_output=True, text=True, timeout=20) + self.assertEqual(ran.returncode, 0, ran.stdout + ran.stderr) + + def test_disabled_logging_build_has_noop_pause_apis(self): + with tempfile.TemporaryDirectory(prefix="meshcore-packet-disabled-") as directory: + for flags in ([], ["-DMESH_DEBUG=1", "-DMESH_USB_LOGGING_DISABLED=1"]): + binary = self.compile(Path(directory), "disabled", ''' +#include +#include +int main(){ + static_assert(!MESH_USB_LOGGING_AVAILABLE,"disabled test profile"); + mesh::noteUsbConsoleCommand("get name");mesh::resumeUsbPacketLogging(); + assert(!mesh::isUsbPacketLoggingAllowed()); +} +''', flags) + ran = subprocess.run([str(binary)], capture_output=True, text=True, timeout=20) + self.assertEqual(ran.returncode, 0, ran.stdout + ran.stderr) + + +if __name__ == "__main__": + unittest.main()