Delay displayed radio preamble advice for two minutes

.github/workflows/run-unit-tests.yml

@@ -493,6 +493,7 @@ jobs:
           python3 -B test/test_radio_profile_spiffs_missing.py -v
           python3 -B test/test_radio_reply_mutation.py
           python3 -B test/test_radio_profile_scan.py
+          python3 -B test/test_radio_profile_runtime_recommendation.py -v
           python3 -B test/test_radio_profile_idle_dispatcher.py -v
           python3 -B test/test_radio_rxps_rejection.py -v
           python3 -B test/test_repeater_radio_timing_integration.py

docs/radio_profiles.md

@@ -868,6 +868,19 @@ The rapid startup hops briefly interrupt reception on each channel; a new
 packet beginning during this test may be missed. An already detected packet
 defers the test instead of being interrupted.
 
+Displayed preamble recommendations and warnings wait until the active pair has
+run for at least two minutes, measured from its first successful RX-to-RX hop.
+Four successful hops in each direction are still required. A pair change starts
+a fresh wait; an unchanged or rejected request does not. Use a temporary lease
+longer than two minutes if you want its recommendation before it expires.
+
+This is a display-only delay. The bounded startup test, guarded maximum switch
+budget, automatic preambles, ordinary scanning and MCU-idle behavior do not wait
+two minutes. Live switch and scan diagnostics remain available, marked pending
+with `wait=Ns` until advice is ready. Waiting does not discard an early maximum
+or replace it with an average. No extra retunes are forced at the deadline; a
+successful normal hop completes the display wait.
+
 Each idle scan starts with **4.6 symbols on the slower
 profile**, then spends the remaining budgeted time on the faster profile,
 also with a **4.6-symbol floor**. Slower
@@ -911,8 +924,9 @@ receiver's setting does not lengthen packets sent by other nodes.
 
 `get radio2.timing` (alias `get radio.timing`) reports the active pair in
 `radio,radio2` order: dwell in chirps, recommended preambles in symbols, and
-the switching/loop allowances. Before calibration it reports `timing self-test
-pending` and the provisional preambles. On nRF52 boards, enabling `radio2`
+the switching/loop allowances. During the two-minute advice wait it reports
+`timing self-test pending`, the remaining wait and the current provisional
+switch allowance/preambles, without a final `need=` recommendation. On nRF52 boards, enabling `radio2`
 uses RTC2 for both retune timing and scan visits (about 31 us resolution);
 turning `radio2` off stops RTC2 and returns to the usual `micros()` clock.
 Previously, the nRF52 `micros()` fallback counted 1,024 Hz RTOS ticks: a real

src/RadioProfiles.h

@@ -55,6 +55,7 @@ class RadioProfiles {
   // the self-tested, guarded switch time in the idle-scan timing model.
   static constexpr uint32_t LoopBudgetUs = 0;
   static constexpr uint8_t SwitchTestSamplesPerDirection = 4;
+  static constexpr uint32_t SwitchRecommendationWindowMs = 120000;
 
   struct ChirpTiming {
     bool valid = false;
@@ -83,20 +84,41 @@ class RadioProfiles {
   uint32_t longest_switch_us = 0;
   uint32_t switch_test_max_us[2] = {};
   uint8_t switch_test_samples[2] = {};
+  uint32_t switch_runtime_started_ms = 0;
+  bool switch_runtime_started = false;
+  bool switch_runtime_ready = false;
 
   void resetSwitchTest() {
     switch_test_max_us[0] = switch_test_max_us[1] = 0;
     switch_test_samples[0] = switch_test_samples[1] = 0;
+    switch_runtime_started_ms = 0;
+    switch_runtime_started = switch_runtime_ready = false;
   }
-  void sampleSwitch(uint8_t from, uint8_t to, uint32_t elapsed_us) {
+  void sampleSwitch(uint8_t from, uint8_t to, uint32_t elapsed_us, uint32_t now_ms = 0) {
     if (!enabled() || from > 1 || to > 1 || from == to || !elapsed_us) return;
     if (switch_test_samples[from] < SwitchTestSamplesPerDirection) ++switch_test_samples[from];
     if (elapsed_us > switch_test_max_us[from]) switch_test_max_us[from] = elapsed_us;
+    // Delay only the displayed recommendation. Startup readiness, guarded
+    // maxima, automatic preambles and scanner behavior remain unchanged.
+    if (!switch_runtime_started) {
+      switch_runtime_started = true;
+      switch_runtime_started_ms = now_ms;
+    }
+    if (switchTestReady()
+        && uint32_t(now_ms - switch_runtime_started_ms) >= SwitchRecommendationWindowMs)
+      switch_runtime_ready = true;
   }
   bool switchTestReady() const {
     return switch_test_samples[0] >= SwitchTestSamplesPerDirection
         && switch_test_samples[1] >= SwitchTestSamplesPerDirection;
   }
+  bool recommendationReady() const { return switch_runtime_ready; }
+  uint32_t recommendationRemainingMs(uint32_t now_ms) const {
+    if (recommendationReady()) return 0;
+    if (!switch_runtime_started) return SwitchRecommendationWindowMs;
+    const uint32_t elapsed = now_ms - switch_runtime_started_ms;
+    return elapsed < SwitchRecommendationWindowMs ? SwitchRecommendationWindowMs - elapsed : 0;
+  }
   uint32_t switchBudgetUs() const {
     const uint32_t observed = switch_test_max_us[0] > switch_test_max_us[1]
         ? switch_test_max_us[0] : switch_test_max_us[1];

src/helpers/RadioProfileCLI.cpp

@@ -630,9 +630,11 @@ void RadioProfileCLI::appendPrimaryChirpWarning(char* reply, size_t capacity, ui
 
 void RadioProfileCLI::appendChirpWarning(char* reply, size_t capacity, const RadioProfiles& preview) {
   if (!capacity || !preview.enabled()) return;
-  if (!preview.switchTestReady()) {
+  if (!preview.recommendationReady()) {
     const size_t used = strlen(reply);
-    if (used < capacity) snprintf(reply + used, capacity - used, "; timing self-test pending");
+    if (used < capacity) snprintf(reply + used, capacity - used,
+        "; timing self-test pending; wait=%lus",
+        (unsigned long)((preview.recommendationRemainingMs(millis()) + 999) / 1000));
     return;
   }
   const auto timing = preview.chirpTiming();
@@ -761,10 +763,12 @@ bool RadioProfileCLI::handle(const char* command, char* reply, size_t capacity,
     const auto& p = *radio_->profiles();
     const auto t = p.chirpTiming();
     if (!p.enabled()) snprintf(reply, capacity, "> off");
-    else if (!p.switchTestReady()) snprintf(reply, capacity,
-        "> timing self-test pending; test=%u/%u,%u/%u; provisional preamble=%u,%u",
+    else if (!p.recommendationReady()) snprintf(reply, capacity,
+        "> timing self-test pending; test=%u/%u,%u/%u; wait=%lus; provisional switch=%luus preamble=%u,%u",
         p.switch_test_samples[0], RadioProfiles::SwitchTestSamplesPerDirection,
         p.switch_test_samples[1], RadioProfiles::SwitchTestSamplesPerDirection,
+        (unsigned long)((p.recommendationRemainingMs(millis()) + 999) / 1000),
+        (unsigned long)p.switchBudgetUs(),
         radio_->profilePreamble(0), radio_->profilePreamble(1));
     else if (!t.valid) snprintf(reply, capacity, "Error: timing unavailable");
     else {
@@ -823,7 +827,7 @@ bool RadioProfileCLI::handle(const char* command, char* reply, size_t capacity,
       if (used < capacity) snprintf(reply + used, capacity - used, "; test=%u/%u,%u/%u%s budget=%luus",
           p.switch_test_samples[0], RadioProfiles::SwitchTestSamplesPerDirection,
           p.switch_test_samples[1], RadioProfiles::SwitchTestSamplesPerDirection,
-          p.switchTestReady() ? " ready" : " pending", (unsigned long)p.switchBudgetUs());
+          p.recommendationReady() ? " ready" : " pending", (unsigned long)p.switchBudgetUs());
       appendChirpWarning(reply, capacity, p);
     }
     return true;

src/helpers/radiolib/RadioLibWrappers.cpp

@@ -562,7 +562,7 @@ mesh::RadioParamApplyResult RadioLibWrapper::tuneProfile(uint8_t profile) {
   // then continue raising the observed maximum as later good hops run.
   // Deferred and rolled-back operations are not samples.
   if (applied && resume && old_profile != profile) {
-    _profiles.sampleSwitch(old_profile, profile, elapsed);
+    _profiles.sampleSwitch(old_profile, profile, elapsed, millis());
   }
   return applied ? mesh::RadioParamApplyResult::APPLIED : mesh::RadioParamApplyResult::FAILED;
 }

test/fixtures/radio_profiles/cli_test.cpp

@@ -43,11 +43,14 @@ struct Fixture {
   }
   void advance(uint32_t ms, bool epoch=true) { g_mock_millis+=ms; if(epoch)clock.epoch+=ms/1000; cli.loop(); }
   void finishTimingTest(uint32_t switch_us=545) {
+    const uint32_t start = g_mock_millis - mesh::RadioProfiles::SwitchRecommendationWindowMs;
     for (unsigned i=0;i<mesh::RadioProfiles::SwitchTestSamplesPerDirection;++i) {
-      radio.p.sampleSwitch(0,1,switch_us);
-      radio.p.sampleSwitch(1,0,switch_us);
+      radio.p.sampleSwitch(0,1,switch_us,start+i);
+      radio.p.sampleSwitch(1,0,switch_us,start+i);
     }
+    radio.p.sampleSwitch(0,1,switch_us,g_mock_millis);
     assert(radio.p.switchTestReady());
+    assert(radio.p.recommendationReady());
   }
 };
 static void permanentScheduleOrder() {
@@ -387,6 +390,44 @@ int main(int argc, char** argv) {
     f.cmd("set radio2 off"); f.advance(2000); assert(!f.radio.p.enabled());
     f.cmd("get radio2.status");
   }
+  {
+    Fixture f;
+    f.cmd("set radio2 910.5,500,7,5,rx");
+    f.advance(2000);
+    for (unsigned i=0;i<mesh::RadioProfiles::SwitchTestSamplesPerDirection;++i) {
+      f.radio.p.sampleSwitch(0,1,545,g_mock_millis);
+      f.radio.p.sampleSwitch(1,0,545,g_mock_millis);
+    }
+    assert(f.radio.p.switchTestReady() && !f.radio.p.recommendationReady());
+    const auto wire_preamble = f.radio.p.preamble(1,32);
+    assert(wire_preamble==64 && f.radio.p.switchBudgetUs()==600);
+    assert(strstr(f.cmd("get radio2"),"rx,64 (auto)"));
+    assert(strstr(f.reply,"wait=120s") && !strstr(f.reply,"WARN"));
+    assert(strstr(f.cmd("get radio2.timing"),"provisional switch=600us"));
+    assert(!strstr(f.reply,"need=") && !strstr(f.reply,"WARN"));
+    f.advance(119999);
+    f.radio.p.sampleSwitch(0,1,545,g_mock_millis);
+    assert(!f.radio.p.recommendationReady());
+    assert(strstr(f.cmd("get radio2.timing"),"wait=1s"));
+    f.advance(1);
+    assert(!f.radio.p.recommendationReady()); // No synthetic retune at deadline.
+    f.radio.p.sampleSwitch(1,0,545,g_mock_millis);
+    assert(f.radio.p.recommendationReady());
+    assert(f.radio.p.preamble(1,32)==wire_preamble && f.radio.p.switchBudgetUs()==600);
+    assert(strstr(f.cmd("get radio2.timing"),"need=32,64"));
+    assert(strstr(f.reply,"WARN recommended preamble: radio2=64"));
+    assert(!strstr(f.reply,"timing self-test pending"));
+    // The UI delay never changes ongoing maximum-based timing policy.
+    f.radio.p.sampleSwitch(0,1,8428,g_mock_millis);
+    assert(f.radio.p.switchBudgetUs()==9271);
+    assert(strstr(f.cmd("get radio2.timing"),"switch=9271us"));
+    f.cmd("set radio2 910.5,500,7,5,rx");
+    assert(f.radio.p.recommendationReady()); // No-op leaves the window intact.
+    f.cmd("set radio2 911.5,500,7,5,rx");
+    f.advance(2000);
+    assert(!f.radio.p.recommendationReady());
+    assert(strstr(f.cmd("get radio2.timing"),"wait=120s"));
+  }
   {
     Fixture f;
     assert(strstr(f.cmd("set radio2 910.5,500,7,5,rx"),"timing self-test pending"));

test/test_radio_profile_runtime_recommendation.py

@@ -0,0 +1,151 @@
+"""Delay displayed advice without changing the scanner's measured-max policy."""
+from pathlib import Path
+import os
+import subprocess
+import tempfile
+import unittest
+
+import test_radio_profile_scan as scan
+from test_radio_receive_contract import method
+
+
+ROOT = Path(__file__).resolve().parents[1]
+
+
+class RuntimeRecommendationTest(unittest.TestCase):
+    def compile_run(self, source):
+        with tempfile.TemporaryDirectory() as folder:
+            cpp, binary = Path(folder) / "test.cpp", Path(folder) / "test"
+            (Path(folder) / "Arduino.h").write_text("#pragma once\n#include <cstdint>\n#include <cmath>\n")
+            cpp.write_text(source, encoding="ascii")
+            built = subprocess.run([os.environ.get("CXX", "g++"), "-std=c++17",
+                "-Wall", "-Wextra", "-fsanitize=address,undefined", "-no-pie",
+                "-fno-omit-frame-pointer", "-I", folder, "-I", str(ROOT / "src"),
+                str(cpp), "-o", str(binary)], capture_output=True, text=True)
+            self.assertEqual(built.returncode, 0, built.stderr)
+            ran = subprocess.run([str(binary)], capture_output=True, text=True)
+            self.assertEqual(ran.returncode, 0, ran.stderr)
+
+    def test_clock_boundaries_resets_and_unchanged_maximum_budget(self):
+        self.compile_run(r'''
+#include <RadioProfiles.h>
+#include <cassert>
+#include <cstdint>
+#include <initializer_list>
+using P=mesh::RadioProfiles;
+P pair() {
+  P p;p.primary={909.5f,500,0,7,5};p.secondary.params=p.primary;
+  p.secondary.params.freq=910.5f;p.secondary.mode=mesh::RadioProfileMode::Rx;
+  return p;
+}
+void train(P& p,uint32_t now,uint32_t a=100,uint32_t b=100) {
+  for(unsigned n=0;n<P::SwitchTestSamplesPerDirection;++n) {
+    p.sampleSwitch(0,1,a,now);p.sampleSwitch(1,0,b,now);
+  }
+  assert(p.switchTestReady() && !p.recommendationReady());
+  assert(p.switch_test_samples[0]==4 && p.switch_test_samples[1]==4);
+}
+void same(const P& a,const P& b) {
+  assert(a.switch_runtime_started==b.switch_runtime_started);
+  assert(a.switch_runtime_ready==b.switch_runtime_ready);
+  assert(a.switch_runtime_started_ms==b.switch_runtime_started_ms);
+  for(unsigned i=0;i<2;++i) {
+    assert(a.switch_test_samples[i]==b.switch_test_samples[i]);
+    assert(a.switch_test_max_us[i]==b.switch_test_max_us[i]);
+  }
+}
+int main() {
+  // Zero is a valid real start, and unsigned millisecond wrap is harmless.
+  for(uint32_t start:{0u,1234u,UINT32_MAX-60000u}) {
+    auto p=pair();assert(p.recommendationRemainingMs(start)==120000);
+    train(p,start);assert(p.switch_runtime_started && p.switch_runtime_started_ms==start);
+    assert(p.switchBudgetUs()==110 && p.preamble(0,32)==32);
+    const auto wire_a=p.preamble(0,32),wire_b=p.preamble(1,32);
+    const auto dwell_a=p.listenUs(0),dwell_b=p.listenUs(1);
+    p.sampleSwitch(0,1,100,start+119999u);
+    assert(!p.recommendationReady() && p.recommendationRemainingMs(start+119999u)==1);
+    p.sampleSwitch(1,0,100,start+120000u);
+    assert(p.recommendationReady() && p.recommendationRemainingMs(start+120000u)==0);
+    assert(p.switchBudgetUs()==110);
+    assert(p.preamble(0,32)==wire_a && p.preamble(1,32)==wire_b);
+    assert(p.listenUs(0)==dwell_a && p.listenUs(1)==dwell_b);
+    p.sampleSwitch(0,1,8428,start+120001u);
+    assert(p.switch_test_max_us[0]==8428 && p.switchBudgetUs()==9271);
+    assert(p.preamble(0,32)==168); // late maximum still affects real scheduling
+    assert(p.switch_test_samples[0]==4 && p.switch_test_samples[1]==4);
+    p.sampleSwitch(1,0,UINT32_MAX,start+120002u);
+    assert(p.switchBudgetUs()==UINT32_MAX); // existing overflow-safe guard
+  }
+  // The old provisional maximum adapts immediately BEFORE two minutes too.
+  {
+    auto p=pair();train(p,0);p.sampleSwitch(0,1,8428,1000);
+    assert(!p.recommendationReady() && p.switchBudgetUs()==9271);
+    assert(p.preamble(0,32)==168);
+    p.sampleSwitch(1,0,8428,120000);
+    assert(p.recommendationReady() && p.switchBudgetUs()==9271);
+  }
+  // Invalid work cannot start the clock; elapsed time without the four good
+  // samples in EACH direction is not recommendation readiness.
+  {
+    auto p=pair();p.sampleSwitch(0,0,100,120000);p.sampleSwitch(0,1,0,120000);
+    p.sampleSwitch(2,0,100,120000);p.sampleSwitch(0,2,100,120000);
+    assert(!p.switch_runtime_started && !p.recommendationReady());
+    p.sampleSwitch(0,1,100,0);p.sampleSwitch(0,1,100,120000);
+    assert(!p.switchTestReady() && !p.recommendationReady());
+    assert(p.recommendationRemainingMs(120000)==0);
+    for(unsigned n=0;n<4;++n) {p.sampleSwitch(0,1,100,120001);p.sampleSwitch(1,0,100,120001);}
+    assert(p.switchTestReady() && p.recommendationReady());
+  }
+  // Pair/lease changes reset the complete timer. No-op publication and a
+  // whole-object rollback preserve it, together with the unchanged maxima.
+  {
+    auto p=pair();train(p,0);p.sampleSwitch(0,1,100,120000);const auto old=p;
+    p.setPrimary(p.primary,p.primary_temporary);p.setSecondary(p.secondary,p.secondary_temporary);same(p,old);
+    auto changed=p.primary;changed.freq+=1;p.setPrimary(changed,false);
+    assert(!p.switchTestReady() && !p.recommendationReady() && !p.switch_runtime_started);
+    assert(p.switchBudgetUs()==0 && p.recommendationRemainingMs(120000)==120000);
+    p=old;same(p,old);p.setSecondary(p.secondary,!p.secondary_temporary);
+    assert(!p.recommendationReady() && !p.switch_runtime_started);
+    p=old;auto disabled=p.secondary;disabled.mode=mesh::RadioProfileMode::Off;
+    p.setSecondary(disabled,false);p.sampleSwitch(0,1,100,120000);
+    assert(!p.switch_runtime_started && !p.recommendationReady());
+  }
+}
+''')
+
+    def test_actual_scanner_keeps_bounded_startup_and_natural_visits(self):
+        source = (ROOT / "src/helpers/radiolib/RadioLibWrappers.cpp").read_text()
+        signatures = [("uint8_t", "beginReconfigure"), ("void", "endReconfigure"),
+                      ("void", "serviceProfileScan")]
+        signatures += [("mesh::RadioParamApplyResult", name) for name in (
+            "tuneProfile", "prepareTransmitProfile", "tryRestoreCodingRate", "trySetParams", "trySetPrimaryParams")]
+        methods = "\n".join(method(source, f"{kind} RadioLibWrapper::{name}(") for kind, name in signatures)
+        methods += "\n" + method(source, "mesh::RadioParamApplyResult RadioLibWrapper::prepareTransmitProfile(uint8_t profile, bool")
+        wrapper = (ROOT / "src/helpers/radiolib/CustomSX1262Wrapper.h").read_text()
+        methods += "\n" + method(wrapper, "void setProfileStandbyWarm(").replace(
+            "void setProfileStandbyWarm(bool enabled) override",
+            "void RadioLibWrapper::setProfileStandbyWarm(bool enabled)")
+        fixture = scan.HARNESS[:scan.HARNESS.index("int main()")].replace("@METHODS@", methods)
+        fixture += r'''
+int main() {
+  RadioLibWrapper w;w.enable();
+  assert(w._profiles.switchTestReady() && !w._profiles.recommendationReady());
+  const auto applies=w.applies;
+  for(unsigned i=0;i<16;++i) w.serviceProfileScan();
+  assert(w.applies==applies); // not repeated startup bursts while advice waits
+  const auto started=w._profiles.switch_runtime_started_ms;
+  elapsed_us=(uint64_t(started)+119999)*1000;
+  w.serviceProfileScan();
+  assert(w._profiles.recommendationReady() && w.applies==applies+1);
+  assert(w._profiles.switchBudgetUs()==1320);
+  const auto old=w._profiles;
+  w.packet=true;auto requested=w._profiles.primary;requested.preamble=64;
+  assert(w.trySetPrimaryParams(requested,true)==mesh::RadioParamApplyResult::BUSY);
+  assert(w._profiles.recommendationReady() && w._profiles.switch_runtime_started_ms==old.switch_runtime_started_ms);
+}
+'''
+        self.compile_run(fixture)
+
+
+if __name__ == "__main__":
+    unittest.main()