Quiet USB packet logs for five minutes after console commands

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; }
 }

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;

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; }
 }

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));

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<std::string> stats_commands;
+static std::vector<std::string> 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<std::string>{oversized_setter.substr(0,256)});

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 {

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; }
 }

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";

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 <helpers/SerialPacketLog.h>
+#include <helpers/BaseSerialInterface.h>
+@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<const char*>{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<const uint8_t*>(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<sizeof(large);++i)hex+="A5";
+#if MESH_PACKET_LOGGING_COMPACT
+ assert(host=="R"+hex+"\n");
+#else
+ assert(host=="stamp RAW: "+hex+"\r\n");
+#endif
+ assert(!mesh::isUsbPacketLoggingAllowed()&&mesh::serialLogDroppedCount()==0);
+ host.clear();node.logRxRaw(2.5f,-92,raw,sizeof(raw));drain();
+ assert(host.empty()&&node.transport.frames==3);
+ assert(console.write(reinterpret_cast<const uint8_t*>(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 <helpers/UsbLogging.h>
+#include <helpers/UsbLoggingClientActivity.h>
+#include <atomic>
+#include <cassert>
+namespace mesh {
+static std::atomic<bool> usb_logging_enabled{true};
+static std::atomic<uint32_t> 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 <helpers/UsbLogging.h>
+#include <cassert>
+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()