Estimate Companion trace timeouts from planned radio transmissions

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

@@ -342,6 +342,7 @@ jobs:
           python3 -B test/test_companion_lost_reply.py -v
           python3 -B test/test_companion_delayed_reply_delivery.py -v
           python3 -B test/test_companion_scheduled_reboot.py -v
+          python3 -B test/test_trace_profile_timing.py -v
           python3 -B test/test_companion_hardware_serial.py -v
           python3 -B test/test_companion_hardware_serial_gps.py -v
           python3 -B test/test_companion_contact_lifetime.py -v

examples/companion_radio/MyMesh.cpp

@@ -7052,7 +7052,7 @@ void MyMesh::handleCmdFrame(size_t len) {
       if (pkt) {
         // Compute before handing ownership to sendDirect(), which releases the
         // packet itself if validation or queueing fails.
-        uint32_t t = _radio->getEstAirtimeFor(9 + path_len + 2);
+        uint32_t t = getTransmitAirtime(pkt, 2 + pkt->payload_len + path_len);
         uint32_t est_timeout = calcDirectTimeoutMillisFor(t, path_len >> path_sz);
         if (sendDirect(pkt, &cmd_frame[10], path_len)) {
           _delayed_replies.armBinaryTrace(est_timeout, _ms->getMillis());
@@ -9585,8 +9585,15 @@ void MyMesh::sendTerminalTraceRoute(const uint8_t* route, uint8_t hash_size,
     return;
   }
 
-  const uint32_t airtime = _radio->getEstAirtimeFor(9 + route_byte_len + 2);
+  mesh::Packet* packet = createTrace(0, 0, flags);
+  if (packet == NULL) {
+    terminalOutput().print("  ERROR: unable to allocate trace packet\r\n");
+    return;
+  }
+  const uint32_t airtime =
+      getTransmitAirtime(packet, 2 + packet->payload_len + route_byte_len);
   if (airtime == 0) {
+    releasePacket(packet);
     terminalOutput().print("  ERROR: unable to estimate trace timeout\r\n");
     return;
   }
@@ -9597,6 +9604,7 @@ void MyMesh::sendTerminalTraceRoute(const uint8_t* route, uint8_t hash_size,
                                                  trace_timeout)
       || trace_timeout > 0x7FFFFFFFU
           - mesh::CompanionDelayedReplies::DELIVERY_GRACE_MS) {
+    releasePacket(packet);
     terminalOutput().print("  ERROR: trace timeout is out of range\r\n");
     return;
   }
@@ -9605,18 +9613,14 @@ void MyMesh::sendTerminalTraceRoute(const uint8_t* route, uint8_t hash_size,
   uint32_t auth = 0;
   getRNG()->random((uint8_t*)&tag, sizeof(tag));
   getRNG()->random((uint8_t*)&auth, sizeof(auth));
+  memcpy(packet->payload, &tag, sizeof(tag));
+  memcpy(&packet->payload[4], &auth, sizeof(auth));
   const uint8_t history = _delayed_replies.reserveTrace(tag, auth, _ms->getMillis());
   if (history == mesh::CompanionDelayedReplies::NO_HISTORY) {
+    releasePacket(packet);
     terminalOutput().print("  ERROR: trace tag is quarantined or reply history is full\r\n");
     return;
   }
-  mesh::Packet* packet = createTrace(tag, auth, flags);
-  if (packet == NULL) {
-    _delayed_replies.abandonTrace(history);
-    terminalOutput().print("  ERROR: unable to allocate trace packet\r\n");
-    return;
-  }
-
   if (!sendDirect(packet, route, static_cast<uint8_t>(route_byte_len))) {
     _delayed_replies.abandonTrace(history);
     terminalOutput().print("  ERROR: unable to send trace\r\n");

src/Dispatcher.cpp

@@ -1449,11 +1449,15 @@ uint8_t Dispatcher::getTransmitProfileMask(const Packet* packet) const {
 }
 
 uint32_t Dispatcher::getTransmitAirtime(const Packet* packet) const {
+  return getTransmitAirtime(packet, packet->getRawLength());
+}
+
+uint32_t Dispatcher::getTransmitAirtime(const Packet* packet, int wire_length) const {
   const uint8_t mask = getTransmitProfileMask(packet);
   uint32_t total = 0;
   for (uint8_t profile = 0; profile < 2; ++profile) {
     if (mask & (1U << profile))
-      total += _radio->getProfileAirtime(profile, packet->getRawLength(), packet->tx_cr);
+      total += _radio->getProfileAirtime(profile, wire_length, packet->tx_cr);
   }
   return total;
 }

src/Dispatcher.h

@@ -610,6 +610,9 @@ protected:
   // Planned fan-out before transport filters; also bounds OTA queue admission.
   uint8_t getTransmitProfileMask(const Packet* packet) const;
   uint32_t getTransmitAirtime(const Packet* packet) const;
+  // TRACE callers supply final DIRECT length; createTrace()'s unset route
+  // bits would otherwise add four transport-code bytes before sendDirect().
+  uint32_t getTransmitAirtime(const Packet* packet, int wire_length) const;
 
 public:
   void begin();

test/fixtures/companion_delayed_reply_delivery/test.cpp

@@ -80,10 +80,11 @@ struct BaseChatMesh {
   Identity self_id;
   mesh::Packet packet;
   Bytes transmitted_payload;
-  unsigned allocations = 0, transmissions = 0, connection_starts = 0;
+  unsigned allocations = 0, releases = 0, transmissions = 0, connection_starts = 0;
   uint32_t txt_send_timeout = 0;
   uint32_t direct_timeout = 5000;
-  bool radio_accepts = true;
+  uint32_t trace_airtime = 100;
+  bool radio_accepts = true, allocation_accepts = true;
   RtcBoundary* getRTCClock() { return &rtc; }
   RngBoundary* getRNG() { return &rng; }
   virtual bool allowRequestTag(uint32_t) { return true; }
@@ -94,17 +95,32 @@ struct BaseChatMesh {
   bool processAck(const uint8_t*, ContactInfo*&) { return false; }
   bool onContactPathRecv(ContactInfo&, uint8_t*, uint8_t, uint8_t*, uint8_t,
                          uint8_t, uint8_t*, uint8_t);
-  mesh::Packet* allocate() { ++allocations; return &packet; }
+  mesh::Packet* allocate() { ++allocations; return allocation_accepts ? &packet : nullptr; }
+  void releasePacket(mesh::Packet*) { ++releases; }
   mesh::Packet* createDatagram(uint8_t, const Identity&, const uint8_t*, const uint8_t* data, size_t len) {
     transmitted_payload.assign(data, data + len);
     return allocate();
   }
   mesh::Packet* createAnonDatagram(uint8_t, const Identity&, const Identity&,
                                   const uint8_t*, const uint8_t*, size_t) { return allocate(); }
-  mesh::Packet* createTrace(uint32_t, uint32_t, uint8_t) { return allocate(); }
-  bool sendDirect(mesh::Packet*, const uint8_t*, uint8_t) { ++transmissions; return radio_accepts; }
+  mesh::Packet* createTrace(uint32_t tag, uint32_t auth, uint8_t flags) {
+    auto* result = allocate();
+    if (result) {
+      memcpy(result->payload, &tag, sizeof(tag));
+      memcpy(result->payload + 4, &auth, sizeof(auth));
+      result->payload[8] = flags;
+      result->payload_len = 9;
+    }
+    return result;
+  }
+  bool sendDirect(mesh::Packet* packet, const uint8_t*, uint8_t) {
+    ++transmissions;
+    if (!radio_accepts) releasePacket(packet);
+    return radio_accepts;
+  }
   bool sendFloodScoped(const ContactInfo&, mesh::Packet*) { ++transmissions; return radio_accepts; }
   uint32_t getTransmitAirtime(mesh::Packet*) const { return 100; }
+  uint32_t getTransmitAirtime(mesh::Packet*, int) const { return trace_airtime; }
   uint32_t calcFloodTimeoutMillisFor(uint32_t) const { return 5000; }
   uint32_t calcDirectTimeoutMillisFor(uint32_t, uint8_t) const { return direct_timeout; }
   void startConnection(const ContactInfo&, uint16_t) { ++connection_starts; }
@@ -828,6 +844,26 @@ int main() {
   // The timeout plus retirement grace must stay in the signed half-range.
   // Test the last reachable tripled base estimate and the next estimate,
   // including a millis wrap while a maximum-duration trace is pending.
+  for(unsigned invalid=0;invalid<7;++invalid) {
+    Fixture f; uint8_t route[176]={};
+    const uint8_t hashes[]={1,1,1,0,3,8,4}, hops[]={1,0,64,1,1,1,44};
+    f.mesh.sendTerminalTraceRoute(invalid==0?nullptr:route,hashes[invalid],hops[invalid],"synthetic");
+    assert(!f.mesh._terminal_trace_pending && f.mesh.allocations==0 && f.mesh.releases==0);
+    assert(f.mesh.rng.calls==0 && f.mesh.transmissions==0);
+    assert(f.mesh._terminal_trace_history==Tracker::NO_HISTORY);
+    const std::string text(f.mesh.terminal_stream.output.begin(),f.mesh.terminal_stream.output.end());
+    const char* expected=invalid<3?"trace path must contain 1-63 prefixes"
+        :invalid<6?"trace hash size must be 1, 2, or 4 bytes":"trace path is too long";
+    assert(text.find(expected)!=std::string::npos);++checks;
+  }
+  {
+    Fixture f;uint8_t route[]={0x12};f.mesh.sendTerminalTraceRoute(route,1,1,"synthetic");
+    assert(f.mesh._terminal_trace_pending);
+    f.mesh.sendTerminalTraceRoute(nullptr,0,0,"ignored");
+    assert(f.mesh.allocations==1 && f.mesh.releases==0 && f.mesh.rng.calls==2 && f.mesh.transmissions==1);
+    const std::string text(f.mesh.terminal_stream.output.begin(),f.mesh.terminal_stream.output.end());
+    assert(text.find("trace to synthetic is still pending")!=std::string::npos);++checks;
+  }
   for(uint32_t start : {100U,0xfffffff0U}) {
     Fixture f;g_mock_millis=start;uint8_t route[]={0x12};
     const uint32_t ceiling=0x7fffffffU-Tracker::DELIVERY_GRACE_MS;
@@ -847,7 +883,8 @@ int main() {
     Fixture f;uint8_t route[]={0x12};
     f.mesh.direct_timeout=(0x7fffffffU-Tracker::DELIVERY_GRACE_MS)/3U+1U;
     f.mesh.sendTerminalTraceRoute(route,1,1,"synthetic");
-    assert(!f.mesh._terminal_trace_pending && f.mesh.transmissions==0 && f.mesh.allocations==0);
+    assert(!f.mesh._terminal_trace_pending && f.mesh.transmissions==0);
+    assert(f.mesh.allocations==1 && f.mesh.releases==1);
     assert(f.mesh.rng.calls==0 && f.mesh._terminal_trace_history==Tracker::NO_HISTORY);
     const std::string text(f.mesh.terminal_stream.output.begin(),f.mesh.terminal_stream.output.end());
     assert(text.find("trace timeout is out of range")!=std::string::npos);
@@ -855,6 +892,49 @@ int main() {
       assert(f.mesh._delayed_replies.reserveTrace(i+1,23,millis())!=Tracker::NO_HISTORY);
     assert(f.mesh._delayed_replies.reserveTrace(99,23,millis())==Tracker::NO_HISTORY);++checks;
   }
+  {
+    Fixture f; uint8_t route[]={0x12}; f.mesh.trace_airtime=0;
+    f.mesh.sendTerminalTraceRoute(route,1,1,"synthetic");
+    assert(!f.mesh._terminal_trace_pending && f.mesh.transmissions==0);
+    assert(f.mesh.allocations==1 && f.mesh.releases==1 && f.mesh.rng.calls==0);
+    assert(f.mesh._terminal_trace_history==Tracker::NO_HISTORY);
+    const std::string text(f.mesh.terminal_stream.output.begin(),f.mesh.terminal_stream.output.end());
+    assert(text.find("unable to estimate trace timeout")!=std::string::npos);
+    for(unsigned i=0;i<Tracker::HISTORY_SIZE;++i)
+      assert(f.mesh._delayed_replies.reserveTrace(i+1,23,millis())!=Tracker::NO_HISTORY);
+    ++checks;
+  }
+  {
+    Fixture f; uint8_t route[]={0x12}; f.mesh.allocation_accepts=false;
+    f.mesh.sendTerminalTraceRoute(route,1,1,"synthetic");
+    assert(!f.mesh._terminal_trace_pending && f.mesh.transmissions==0);
+    assert(f.mesh.allocations==1 && f.mesh.releases==0 && f.mesh.rng.calls==0);
+    const std::string text(f.mesh.terminal_stream.output.begin(),f.mesh.terminal_stream.output.end());
+    assert(text.find("unable to allocate trace packet")!=std::string::npos);++checks;
+  }
+  {
+    Fixture f; uint8_t route[]={0x12};
+    for(unsigned i=0;i<Tracker::HISTORY_SIZE;++i)
+      assert(f.mesh._delayed_replies.reserveTrace(i+1,23,millis())!=Tracker::NO_HISTORY);
+    f.mesh.sendTerminalTraceRoute(route,1,1,"synthetic");
+    assert(!f.mesh._terminal_trace_pending && f.mesh.transmissions==0);
+    assert(f.mesh.allocations==1 && f.mesh.releases==1 && f.mesh.rng.calls==2);
+    const std::string text(f.mesh.terminal_stream.output.begin(),f.mesh.terminal_stream.output.end());
+    assert(text.find("trace tag is quarantined or reply history is full")!=std::string::npos);++checks;
+  }
+  {
+    Fixture f; uint8_t route[]={0x12}; f.mesh.radio_accepts=false;
+    for(unsigned i=0;i<Tracker::HISTORY_SIZE+2;++i) {
+      f.mesh.sendTerminalTraceRoute(route,1,1,"synthetic");
+      assert(!f.mesh._terminal_trace_pending && f.mesh.allocations==i+1 && f.mesh.releases==i+1);
+    }
+    f.mesh.radio_accepts=true;
+    f.mesh.sendTerminalTraceRoute(route,1,1,"synthetic");
+    assert(f.mesh._terminal_trace_pending && f.mesh.allocations==f.mesh.releases+1);
+    uint32_t tag,auth; memcpy(&tag,f.mesh.packet.payload,4);memcpy(&auth,f.mesh.packet.payload+4,4);
+    assert(tag==f.mesh._terminal_trace_tag && auth==f.mesh._terminal_trace_auth);
+    assert(tag==17 && auth==23 && f.mesh.packet.payload[8]==0);++checks;
+  }
   {
     Fixture f;f.mesh.sendTerminalLogin(f.mesh.recipient,"x");
     assert(f.mesh._terminal_login_pending && f.mesh.transmissions==1);

test/fixtures/trace_profile_timing.cpp

@@ -0,0 +1,289 @@
+#include <array>
+#include <cassert>
+#include <cstdint>
+#include <cstdio>
+#include <cstring>
+#include <string>
+#include <vector>
+#include <Packet.h>
+#include <RadioProfiles.h>
+#include <helpers/CompanionDelayedReplies.h>
+#include <helpers/TracePathHelpers.h>
+
+#define ERR_EVENT_FULL 1
+#include "constants.inc"
+
+class RadioLibWrapper {
+public:
+  mesh::RadioProfiles _profiles;
+  uint16_t profilePreamble(uint8_t profile) { return _profiles.preamble(profile, 32); }
+  uint32_t getEstAirtimeFor(int) { return 77; }
+  uint32_t getProfileAirtime(uint8_t, int, uint8_t = 0);
+};
+struct Call { uint8_t profile; int bytes; uint8_t cr; };
+struct Radio {
+  RadioLibWrapper driver;
+  bool expose_profiles = true;
+  uint8_t active = 0;
+  unsigned legacy_calls = 0;
+  std::vector<Call> calls;
+  mesh::RadioProfiles* profiles() { return expose_profiles ? &driver._profiles : nullptr; }
+  uint32_t getEstAirtimeFor(int length) {
+    ++legacy_calls;
+    return driver.getProfileAirtime(active, length);
+  }
+  uint32_t getProfileAirtime(uint8_t profile, int length, uint8_t cr = 0) {
+    calls.push_back({profile, length, cr});
+    return driver.getProfileAirtime(profile, length, cr);
+  }
+};
+struct Clock { uint32_t now = 100; uint32_t getMillis() const { return now; } };
+struct Manager {
+  std::array<mesh::Packet, 4> packets;
+  std::array<bool, 4> used{};
+  std::vector<mesh::Packet*> queued;
+  mesh::Packet* allocNew() {
+    for (unsigned i = 0; i != used.size(); ++i) if (!used[i]) {
+      used[i] = true; return &packets[i];
+    }
+    return nullptr;
+  }
+  bool queueOutbound(mesh::Packet* packet, uint8_t, uint32_t) {
+    queued.push_back(packet); return true;
+  }
+  void free(mesh::Packet* packet) {
+    for (unsigned i = 0; i != used.size(); ++i) if (&packets[i] == packet) {
+      assert(used[i]); used[i] = false; return;
+    }
+    assert(false);
+  }
+};
+namespace mesh {
+class Dispatcher {
+public:
+  Radio* _radio = nullptr;
+  Manager manager;
+  Manager* _mgr = &manager;
+  Clock clock;
+  Clock* _ms = &clock;
+  bool radio_available = true, receive_context_active = false;
+  uint8_t receive_context_profile = 0;
+  uint32_t receive_context_generation = 0;
+  uint16_t _err_flags = 0;
+  Packet* obtainNewPacket();
+  void releasePacket(Packet* packet) { _mgr->free(packet); }
+  uint32_t futureMillis(uint32_t delta) const { return _ms->getMillis() + delta; }
+  bool isPacketRadioCurrent(const Packet*) const { return true; }
+  bool allowRadioProfileCross(const Packet*) { return true; }
+  void onSendFail(Packet*) {}
+  void onRadioProfileCopyQueued(Packet*, const Packet*, uint8_t) {}
+  void onTracePacketQueuedForSend(Packet*) {}
+  uint8_t getTransmitProfileMask(const Packet*) const;
+  uint32_t getTransmitAirtime(const Packet*) const;
+  uint32_t getTransmitAirtime(const Packet*, int) const;
+  bool queueOutboundPacket(Packet*, uint8_t, uint32_t);
+  bool sendPacket(Packet*, uint8_t, uint32_t);
+};
+struct Tables { void markSent(const Packet*) {} };
+static uint8_t getTraceDirectPriority(const Packet*) { return 0; }
+class Mesh : public Dispatcher {
+public:
+  Tables tables;
+  Tables* _tables = &tables;
+  void maybeScheduleDirectRetry(Packet*, uint8_t) {}
+  Packet* createTrace(uint32_t, uint32_t, uint8_t);
+  bool sendDirect(Packet*, const uint8_t*, uint8_t, uint32_t = 0);
+};
+}
+struct Output {
+  void print(const char*) {}
+  template<class... Args> void printf(const char*, Args...) {}
+};
+struct Rng {
+  unsigned calls = 0;
+  void random(uint8_t* out, size_t length) {
+    const uint32_t value = calls++ % 2 ? 23 : 17;
+    assert(length == sizeof(value)); memcpy(out, &value, length);
+  }
+};
+struct Serial : BaseSerialInterface {
+  void enable() override {}
+  void disable() override {}
+  bool isEnabled() const override { return true; }
+  bool isConnected() const override { return true; }
+  bool isReadBusy() const override { return false; }
+  bool isWriteBusy() const override { return false; }
+  size_t writeFrame(const uint8_t*, size_t size) override { return size; }
+  size_t checkRecvFrame(uint8_t*) override { return 0; }
+};
+namespace StrHelper {
+static void strzcpy(char* out, const char* text, size_t capacity) { snprintf(out, capacity, "%s", text); }
+}
+class MyMesh : public mesh::Mesh {
+public:
+  mesh::CompanionDelayedReplies _delayed_replies;
+  bool _terminal_trace_pending = false;
+  uint8_t _terminal_trace_history = 255, _terminal_trace_hash_size = 0;
+  uint32_t _terminal_trace_tag = 0, _terminal_trace_auth = 0;
+  uint32_t _terminal_trace_sent_at = 0, _terminal_trace_expires_at = 0;
+  char _terminal_trace_target[32] = {};
+  Output output;
+  Rng rng;
+  Serial serial;
+  Serial* _serial = &serial;
+  uint8_t cmd_frame[MAX_FRAME_SIZE + 1] = {};
+  unsigned error = 0;
+  void serviceTerminalTrace() {}
+  void serviceBinaryTraceReply() {}
+  Output& terminalOutput() { return output; }
+  Rng* getRNG() { return &rng; }
+  void writeErrFrame(uint8_t code) { error = code; }
+  uint32_t calcDirectTimeoutMillisFor(uint32_t, uint8_t) const;
+  void sendTerminalTraceRoute(const uint8_t*, uint8_t, uint8_t, const char*);
+  void handleTraceFrame(size_t);
+};
+#include "production.inc"
+
+static void configure(Radio& radio, unsigned mode, bool swapped) {
+  auto& p = radio.driver._profiles;
+  p.primary = {915, 125, 32, 11, 8};
+  p.secondary.params = {916, 500, 512, 7, 5};
+  if (swapped) {
+    const auto primary = p.primary;
+    p.primary = p.secondary.params;
+    p.secondary.params = primary;
+  }
+  p.secondary.mode = mesh::RadioProfileMode::RxTx;
+  p.cross = mesh::RadioCrossMode::On;
+  switch (mode) {
+    case 0: p.secondary.mode = mesh::RadioProfileMode::Off; break;
+    case 1: p.secondary.mode = mesh::RadioProfileMode::Rx; break;
+    case 2: p.cross = mesh::RadioCrossMode::Off; break;
+    case 4: p.cross = mesh::RadioCrossMode::Auto; break;
+    case 5: p.cross = mesh::RadioCrossMode::Auto; p.primary_temporary = true; break;
+    case 6: p.cross = mesh::RadioCrossMode::Auto; p.primary_temporary = p.secondary_temporary = true; break;
+    case 7: p.secondary.params.protocol = mesh::RadioProfileProtocol::Meshtext; break;
+    case 8: p.secondary.params.protocol = mesh::RadioProfileProtocol::Ethernet; break;
+    case 9: radio.expose_profiles = false; p.secondary.mode = mesh::RadioProfileMode::Off; break;
+    default: break;
+  }
+  assert(p.automaticPreambleFits());
+}
+
+static unsigned expectedMask(unsigned mode) { return mode == 3 || mode == 4 || mode == 6 ? 3 : 1; }
+static unsigned verify(MyMesh& node, Radio& radio, unsigned mode,
+                       const uint8_t* route, uint8_t bytes, uint8_t flags,
+                       uint8_t hops, bool terminal) {
+  if (node.error) fprintf(stderr, "trace admission error=%u mode=%u bytes=%u flags=%u hops=%u terminal=%u\n",
+      node.error, mode, bytes, flags, hops, terminal);
+  assert(node.error == 0);
+  const unsigned mask = expectedMask(mode);
+  unsigned queued_mask = 0;
+  for (const auto* packet : node.manager.queued) {
+    uint8_t wire[MAX_TRANS_UNIT];
+    const unsigned length = packet->writeTo(wire);
+    assert(length == unsigned(11 + bytes) && packet->getRawLength() == int(length));
+    assert(packet->isRouteDirect() && packet->path_len == 0 && packet->payload_len == 9 + bytes);
+    assert(packet->payload[8] == flags && memcmp(packet->payload + 9, route, bytes) == 0);
+    uint32_t tag, auth; memcpy(&tag, packet->payload, 4); memcpy(&auth, packet->payload + 4, 4);
+    assert(tag == 17 && auth == 23 && "trace payload must retain final tag/auth");
+    queued_mask |= 1U << packet->radio_profile;
+  }
+  assert(queued_mask == mask && "estimated mask must match actual trace queue admission");
+  uint32_t airtime = 0;
+  for (unsigned profile = 0; profile != 2; ++profile) if (mask & (1U << profile))
+    airtime += radio.driver.getProfileAirtime(profile, 11 + bytes);
+  const uint32_t base = 500U + (6U * airtime + 250U) * ((hops & 63U) + 1U);
+  const uint32_t observed = terminal ? node._terminal_trace_expires_at - node.clock.now
+                                    : node._delayed_replies.trace.timeout;
+  // Diagnose metadata at the wire boundary before checking the resulting timer.
+  for (const auto& call : radio.calls)
+    assert(call.bytes == 11 + bytes && "trace timing must use final serialized wire length");
+  assert(observed == base * (terminal ? 3U : 1U)
+      && "trace timeout must follow selected profiles");
+  assert(radio.legacy_calls == 0 && "trace timeout must follow selected profiles");
+  assert(radio.calls.size() == node.manager.queued.size());
+  for (const auto& call : radio.calls) assert((mask & (1U << call.profile)) && call.cr == 0);
+  return observed;
+}
+
+static unsigned producerChecks() {
+  unsigned cases = 0;
+  for (unsigned mode = 0; mode != 10; ++mode) for (bool swapped : {false, true})
+  for (bool terminal : {false, true}) for (uint8_t hash_size : {1, 2, 4, 8})
+  for (uint8_t hops : {1, 7, 20, 21, 31, 41, 43, 63, 64}) {
+    const unsigned bytes = unsigned(hash_size) * hops;
+    if (bytes > MAX_PACKET_PAYLOAD - 9 || (!terminal && bytes > MAX_FRAME_SIZE - 10)
+        || (terminal && (hash_size == 8 || hops == 64))) continue;
+    uint8_t route[MAX_PACKET_PAYLOAD] = {};
+    for (unsigned i = 0; i < bytes; ++i) route[i] = uint8_t(i + 1);
+    const uint8_t flags = hash_size == 8 ? 3 : mesh::traceFlagsForHashSize(hash_size);
+    uint32_t previous_timeout = 0;
+    for (uint8_t active : {0, 1}) {
+      if ((mode == 0 || mode == 9) && active == 1) continue;
+      Radio radio; configure(radio, mode, swapped); radio.active = active;
+      MyMesh node; node._radio = &radio;
+      if (terminal) {
+        node.sendTerminalTraceRoute(route, hash_size, hops, "synthetic");
+        assert(node._terminal_trace_pending && node.rng.calls == 2);
+      } else {
+        node.cmd_frame[0] = CMD_SEND_TRACE_PATH;
+        const uint32_t tag = 17, auth = 23;
+        memcpy(node.cmd_frame + 1, &tag, 4); memcpy(node.cmd_frame + 5, &auth, 4);
+        node.cmd_frame[9] = flags;
+        memcpy(node.cmd_frame + 10, route, bytes);
+        node.handleTraceFrame(10 + bytes);
+        assert(node._delayed_replies.hasBinaryTrace() && node.rng.calls == 0);
+      }
+      const auto timeout = verify(node, radio, mode, route, bytes, flags, hops, terminal);
+      if (active) assert(previous_timeout == timeout && "scanner visits must not change trace timeout");
+      previous_timeout = timeout;
+      ++cases;
+    }
+  }
+  return cases;
+}
+
+static unsigned helperChecks() {
+  unsigned cases = 0;
+  for (uint8_t origin : {0, 1}) for (uint8_t policy : {mesh::RADIO_TX_AUTO, mesh::RADIO_TX_PRIMARY,
+      mesh::RADIO_TX_SECONDARY, mesh::RADIO_TX_BOTH, mesh::RADIO_TX_OFF})
+  for (bool reply : {false, true}) for (bool force : {false, true})
+  for (uint8_t reply_policy : {mesh::RADIO_TX_BOTH, mesh::RADIO_TX_SECONDARY})
+  for (uint8_t route : {ROUTE_TYPE_FLOOD, ROUTE_TYPE_DIRECT, ROUTE_TYPE_TRANSPORT_DIRECT}) {
+    Radio radio; configure(radio, 1, false);
+    auto& profiles = radio.driver._profiles;
+    profiles.reply_tx = reply_policy; profiles.reply_force = force;
+    MyMesh node; node._radio = &radio;
+    auto* packet = node.obtainNewPacket(); assert(packet);
+    packet->header = route | (PAYLOAD_TYPE_TXT_MSG << PH_TYPE_SHIFT);
+    packet->payload_len = 57; packet->setPathHashSizeAndCount(3, 7);
+    packet->transport_codes[0] = 0x1234; packet->transport_codes[1] = 0x5678;
+    memset(packet->path, 0x21, sizeof(packet->path));
+    memset(packet->payload, 0x43, sizeof(packet->payload));
+    packet->radio_profile = origin; packet->tx_radio = policy;
+    packet->radio_reply = reply; packet->radio_reply_force = force;
+    packet->tx_cr = 8;
+    uint8_t wire[MAX_TRANS_UNIT]; const unsigned length = packet->writeTo(wire);
+    const uint8_t effective_policy = reply && policy == mesh::RADIO_TX_AUTO ? reply_policy : policy;
+    unsigned mask = effective_policy == mesh::RADIO_TX_AUTO ? 1
+        : effective_policy == mesh::RADIO_TX_OFF ? 0
+        : effective_policy & (reply && force ? 3 : 1);
+    uint32_t expected = 0, supplied = 0;
+    for (unsigned profile = 0; profile != 2; ++profile) if (mask & (1U << profile)) {
+      expected += radio.driver.getProfileAirtime(profile, length, 8);
+      supplied += radio.driver.getProfileAirtime(profile, 123, 8);
+    }
+    assert(node.getTransmitProfileMask(packet) == mask);
+    assert(node.getTransmitAirtime(packet) == expected && "existing one-argument airtime must remain unchanged");
+    assert(node.getTransmitAirtime(packet, 123) == supplied);
+    node.releasePacket(packet);
+    ++cases;
+  }
+  return cases;
+}
+
+int main() {
+  const unsigned producers = producerChecks(), helpers = helperChecks();
+  printf("PASS: trace timing %u producer cases, %u existing/helper policy cases\n", producers, helpers);
+}

test/test_trace_profile_timing.py

@@ -0,0 +1,104 @@
+#!/usr/bin/env python3
+"""Execute trace producers, profile admission and complete wire-length timing."""
+from pathlib import Path
+import re
+import shutil
+import subprocess
+import sys
+import tempfile
+import unittest
+
+from test_replay_reset_integration import extract_braced
+
+
+ROOT = Path(__file__).resolve().parents[1]
+FIXTURE = ROOT / "test/fixtures/trace_profile_timing.cpp"
+
+
+class TraceProfileTimingTests(unittest.TestCase):
+    def run_fixture(self, mutation=None):
+        companion = (ROOT / "examples/companion_radio/MyMesh.cpp").read_text()
+        dispatcher = (ROOT / "src/Dispatcher.cpp").read_text()
+        mesh = (ROOT / "src/Mesh.cpp").read_text()
+        driver = (ROOT / "src/helpers/radiolib/RadioLibWrappers.cpp").read_text()
+        methods = "namespace mesh {\n"
+        for signature in (
+            "Packet* Dispatcher::obtainNewPacket(",
+            "bool Dispatcher::queueOutboundPacket(",
+            "uint8_t Dispatcher::getTransmitProfileMask(",
+            "uint32_t Dispatcher::getTransmitAirtime(const Packet* packet) const",
+            "uint32_t Dispatcher::getTransmitAirtime(const Packet* packet, int wire_length) const",
+            "bool Dispatcher::sendPacket(",
+        ):
+            methods += extract_braced(dispatcher, signature) + "\n"
+        for signature in ("Packet* Mesh::createTrace(", "bool Mesh::sendDirect("):
+            methods += extract_braced(mesh, signature) + "\n"
+        methods += "}\n" + extract_braced(driver, "uint32_t RadioLibWrapper::getProfileAirtime(") + "\n"
+        terminal = extract_braced(companion, "void MyMesh::sendTerminalTraceRoute(")
+        binary = extract_braced(companion, "} else if (cmd_frame[0] == CMD_SEND_TRACE_PATH")
+        if mutation:
+            terminal, binary = mutation(terminal, binary)
+        methods += extract_braced(companion, "uint32_t MyMesh::calcDirectTimeoutMillisFor(") + "\n"
+        methods += terminal + "\nvoid MyMesh::handleTraceFrame(size_t len) {\n"
+        methods += binary.replace("} else if", "if", 1) + "\n}\n"
+        constants = "\n".join(re.findall(
+            r"^#define (?:CMD_SEND_TRACE_PATH|ERR_CODE_BAD_STATE|ERR_CODE_ILLEGAL_ARG|ERR_CODE_TABLE_FULL|SEND_TIMEOUT_BASE_MILLIS|DIRECT_SEND_PERHOP_FACTOR|DIRECT_SEND_PERHOP_EXTRA_MILLIS)\s+.+$",
+            companion, re.MULTILINE))
+        compiler = shutil.which("g++") or shutil.which("clang++")
+        self.assertIsNotNone(compiler, "a host C++17 compiler is required")
+        cache = Path.home() / ".cache"
+        cache.mkdir(parents=True, exist_ok=True)
+        with tempfile.TemporaryDirectory(prefix="trace-profile-timing-", dir=cache) as directory:
+            work = Path(directory)
+            (work / "production.inc").write_text(methods, encoding="ascii")
+            (work / "constants.inc").write_text(constants, encoding="ascii")
+            binary_path = work / "trace"
+            sanitizers = (["-fsanitize=address,undefined", "-fno-sanitize-recover=all",
+                           "-fno-pie", "-no-pie"] if sys.platform.startswith("linux") else [])
+            built = subprocess.run([compiler, "-std=c++17", "-Wall", "-Wextra", "-Werror",
+                "-Wno-unused-parameter", "-Wno-sign-compare", *sanitizers, "-I" + str(work),
+                "-I" + str(ROOT / "src"), "-I" + str(ROOT / "test/mocks"),
+                str(FIXTURE), str(ROOT / "src/Packet.cpp"),
+                str(ROOT / "src/helpers/CompanionDelayedReplies.cpp"), "-o", str(binary_path)],
+                capture_output=True, text=True, timeout=60)
+            self.assertEqual(built.returncode, 0, built.stdout + built.stderr)
+            return subprocess.run([str(binary_path)], capture_output=True, text=True, timeout=20)
+
+    def test_actual_trace_producers_mask_admission_and_complete_wire_length(self):
+        result = self.run_fixture()
+        self.assertEqual(result.returncode, 0, result.stdout + result.stderr)
+        self.assertIn("PASS: trace timing", result.stdout)
+
+    def test_legacy_current_radio_estimates_fail_each_producer(self):
+        for terminal in (False, True):
+            def legacy(text, framed):
+                selected = text if terminal else framed
+                selected, count = re.subn(
+                    r"getTransmitAirtime\((?:packet|pkt),\s*2 \+ (?:packet|pkt)->payload_len \+ (route_byte_len|path_len)\)",
+                    lambda match: "_radio->getEstAirtimeFor(11 + " + match[1] + ")", selected)
+                self.assertEqual(count, 1)
+                return (selected, framed) if terminal else (text, selected)
+            with self.subTest(terminal=terminal):
+                result = self.run_fixture(legacy)
+                self.assertNotEqual(result.returncode, 0)
+                self.assertIn("trace timeout must follow selected profiles", result.stderr)
+
+    def test_unset_route_length_and_omitted_appended_bytes_fail_each_producer(self):
+        for terminal in (False, True):
+            for route_bytes in (True, False):
+                def wrong_length(text, framed):
+                    selected = text if terminal else framed
+                    selected, count = re.subn(
+                        r"2 \+ ((?:packet|pkt))->payload_len \+ (route_byte_len|path_len)",
+                        lambda match: match[1] + "->getRawLength()"
+                            + (" + " + match[2] if route_bytes else ""), selected)
+                    self.assertEqual(count, 1)
+                    return (selected, framed) if terminal else (text, selected)
+                with self.subTest(terminal=terminal, route_bytes=route_bytes):
+                    result = self.run_fixture(wrong_length)
+                    self.assertNotEqual(result.returncode, 0)
+                    self.assertIn("trace timing must use final serialized wire length", result.stderr)
+
+
+if __name__ == "__main__":
+    unittest.main()