Arrival time fix perhaps (#11274)

* Add explicit presence for MeshPacket.rx_time (arrival time)

rx_time is now proto3 optional with a has_rx_time presence bit, matching
the rx_rssi treatment. A node with no GPS and no phone connected yet has
no time source at all, so a bare 0 was indistinguishable from a genuine
1970-01-01 reading; downstream consumers (replay packets, JSON
serialization) now check has_rx_time instead of the value.

* Dedupe rx_time stamping into a shared helper; trim a debug log string

Extract the repeated haveTime/rx_time/has_rx_time stamp logic (5 call
sites across Router.cpp, MeshBeaconModule.cpp, MeshService.cpp) into
Router::computeRxTimeStamp()/stampRxTime(). Also shorten the new RTC.cpp
LOG_DEBUG string. Saves 48 bytes of flash on rak4631 (measured), no
behavior change.

* Fix has_rx_rssi presence carried unconditionally through StoreForward replay

preparePayload() set has_rx_rssi = true unconditionally on replay, regardless
of whether the packet's rx_rssi at store time was a genuine measurement (e.g.
MQTT-relayed packets carry no real RSSI). Store the presence bit alongside
rx_rssi in PacketHistoryStruct and restore it on replay instead.

Flagged by Copilot on #11271 (same root cause the has_rx_time explicit
presence work fixes) but never addressed before that PR merged.

* Trim comment blocks to the repo's 1-2 line guideline

.github/copilot-instructions.md:338 caps code comments at 1-2 lines; several
blocks added across the rx_time explicit-presence work ran well past that.
Also consolidates Time.cpp's file-level doc comment into Time.h, where the
rest of the Time:: API contract already lives.

No behavior change.

* Add rx_time explicit-presence test coverage

- test_meshpacket_serializer: has_rx_time=false fixture plus tests asserting
  JsonSerialize/JsonSerializeEncrypted emit 0 rather than leaking the
  millis() placeholder, alongside the has_rx_time=true baseline.
- test_stream_api: two tests driving a real PhoneAPI handshake (want_config_id
  through STATE_SEND_PACKETS) that simulate a phone time-giving transaction
  arriving before vs. after a queued packet is drained - covering both the
  reconciled and the ships-with-placeholder-absent paths of
  MeshService::reconcilePendingRxTimes().

* Fix three correctness issues flagged in review

- Time.h: drop the reserved-identifier include guard (_MT_TIME_H); pragma
  once already covers it, matching convention elsewhere (e.g. RTC.h).
- Time.cpp: rebase getMillis64()'s wrap accumulator when the test seam
  swaps clock sources, so a real<->injected clock jump isn't miscounted
  as a genuine 32-bit wrap.
- NodeInfoModule: the 12h reply-suppression window is a local dedup
  duration, not a wall-clock reading - switch it to Time::getMillis64()
  so RTC-quality jumps and replayed packets' stale rx_time can't perturb
  it.
- StoreForwardModule: has_rx_time was derived from *current* RTC quality
  at replay time rather than stored at capture time, so a history entry
  saved while time-blind could be misreported as a valid epoch once the
  clock later improved. Persist the presence bit in PacketHistoryStruct
  instead.

* tryfix CI

* post review fixes

* more test fixes

Author: NomDeTom

protobufs

@@ -0,0 +1,33 @@
+// See UptimeClock.h for the full contract.
+#include "UptimeClock.h"
+#include <Arduino.h>
+
+uint32_t Time::getMillis()
+{
+#ifdef PIO_UNIT_TESTING
+    if (Time::useTestClock)
+        return Time::testNowMs;
+#endif
+    return millis();
+}
+
+uint64_t Time::getMillis64()
+{
+    static uint32_t lastLow = 0;  // last 32-bit sample
+    static uint32_t highWord = 0; // number of observed wraps
+
+    uint32_t now = Time::getMillis();
+#ifdef PIO_UNIT_TESTING
+    // A test swapping clock sources (real <-> injected) can make `now` jump backward for
+    // reasons other than a genuine wrap - rebase rather than miscount it as one.
+    if (Time::clockSourceChanged) {
+        lastLow = now;
+        highWord = 0;
+        Time::clockSourceChanged = false;
+    }
+#endif
+    if (now < lastLow)
+        highWord++; // low word wrapped since last call
+    lastLow = now;
+    return (static_cast<uint64_t>(highWord) << 32) | now;
+}

src/UptimeClock.cpp

@@ -0,0 +1,46 @@
+#pragma once
+
+#include <cstdint>
+
+// Monotonic uptime clock, injectable so tests can drive a virtual timebase instead of sleeping.
+// Uptime only; see gps/RTC.h for wall-clock. Not named Time.h: -Isrc would shadow C's <time.h>.
+namespace Time
+{
+#ifdef PIO_UNIT_TESTING
+// Test-only virtual clock; OFF by default so suites relying on real time are unaffected.
+inline uint32_t testNowMs = 0;
+inline bool useTestClock = false;
+inline bool clockSourceChanged = true; // forces getMillis64() to rebase its wrap accumulator
+
+inline void setTestMillis(uint32_t ms)
+{
+    testNowMs = ms;
+    useTestClock = true;
+    clockSourceChanged = true;
+}
+inline void advanceTestMillis(uint32_t deltaMs)
+{
+    // Advancing from 0 after getMillis64() sampled the real clock steps backward, which would
+    // otherwise be miscounted as a wrap.
+    if (!useTestClock)
+        clockSourceChanged = true;
+    testNowMs += deltaMs;
+    useTestClock = true;
+}
+// Restore real-clock behaviour (call in test tearDown if a suite mixes real and fake time).
+inline void useRealClock()
+{
+    useTestClock = false;
+    testNowMs = 0;
+    clockSourceChanged = true;
+}
+#endif
+
+/// Milliseconds since boot, 32-bit (wraps ~49.7 days). Drop-in for millis().
+uint32_t getMillis();
+
+/// Milliseconds since boot, 64-bit, rollover-immune. Must be polled at least once per ~49.7-day
+/// wrap window to catch every wrap, and keeps mutable static carry state, so it is NOT ISR-safe.
+uint64_t getMillis64();
+
+} // namespace Time

src/UptimeClock.h

@@ -2,6 +2,7 @@
 #include "configuration.h"
 #include "detect/ScanI2C.h"
 #include "main.h"
+#include "mesh/MeshService.h"
 #include "modules/NodeInfoModule.h"
 #include <Throttle.h>
 #include <sys/time.h>
@@ -17,12 +18,16 @@ uint32_t lastSetFromPhoneNtpOrGps = 0;
 static uint32_t lastTimeValidationWarning = 0;
 static const uint32_t TIME_VALIDATION_WARNING_INTERVAL_MS = 15000; // 15 seconds
 
-static void triggerNodeInfoCheckOnTimeSource(RTCQuality oldQuality, RTCQuality newQuality)
+static void onTimeSourceQualityChanged(RTCQuality oldQuality, RTCQuality newQuality)
 {
     if (oldQuality == RTCQualityNone && newQuality > RTCQualityNone && nodeInfoModule) {
         LOG_DEBUG("Time source acquired (%s -> %s), triggering NodeInfo recheck", RtcName(oldQuality), RtcName(newQuality));
         nodeInfoModule->triggerImmediateNodeInfoCheck();
     }
+    if (oldQuality < RTCQualityFromNet && newQuality >= RTCQualityFromNet && service) {
+        LOG_DEBUG("RTC net quality reached (%s -> %s), reconciling rx_time", RtcName(oldQuality), RtcName(newQuality));
+        service->reconcilePendingRxTimes();
+    }
 }
 
 RTCQuality getRTCQuality()
@@ -128,7 +133,7 @@ RTCSetResult readFromRTC()
             timeStartMsec = now;
             zeroOffsetSecs = tv.tv_sec;
             currentQuality = RTCQualityDevice;
-            triggerNodeInfoCheckOnTimeSource(oldQuality, currentQuality);
+            onTimeSourceQualityChanged(oldQuality, currentQuality);
         }
         return RTCSetResultSuccess;
     } else {
@@ -174,7 +179,7 @@ RTCSetResult readFromRTC()
             timeStartMsec = now;
             zeroOffsetSecs = tv.tv_sec;
             currentQuality = RTCQualityDevice;
-            triggerNodeInfoCheckOnTimeSource(oldQuality, currentQuality);
+            onTimeSourceQualityChanged(oldQuality, currentQuality);
         }
         return RTCSetResultSuccess;
     } else {
@@ -210,7 +215,7 @@ RTCSetResult readFromRTC()
                 timeStartMsec = now;
                 zeroOffsetSecs = tv.tv_sec;
                 currentQuality = RTCQualityDevice;
-                triggerNodeInfoCheckOnTimeSource(oldQuality, currentQuality);
+                onTimeSourceQualityChanged(oldQuality, currentQuality);
             }
             return RTCSetResultSuccess;
         }
@@ -235,7 +240,7 @@ RTCSetResult readFromRTC()
             timeStartMsec = now;
             zeroOffsetSecs = tv.tv_sec;
             currentQuality = RTCQualityDevice;
-            triggerNodeInfoCheckOnTimeSource(oldQuality, currentQuality);
+            onTimeSourceQualityChanged(oldQuality, currentQuality);
         }
         return RTCSetResultSuccess;
     }
@@ -381,7 +386,7 @@ RTCSetResult perhapsSetRTC(RTCQuality q, const struct timeval *tv, bool forceUpd
 #endif
 
         readFromRTC();
-        triggerNodeInfoCheckOnTimeSource(oldQuality, currentQuality);
+        onTimeSourceQualityChanged(oldQuality, currentQuality);
         return RTCSetResultSuccess;
     } else {
         return RTCSetResultNotSet; // RTC was already set with a higher quality time

src/gps/RTC.cpp

@@ -12,6 +12,7 @@
 #include "Power.h"
 #include "PowerFSM.h"
 #include "TypeConversions.h"
+#include "UptimeClock.h"
 #include "gps/RTC.h"
 #include "graphics/draw/MessageRenderer.h"
 #include "main.h"
@@ -180,6 +181,36 @@ NodeNum MeshService::getNodenumFromRequestId(uint32_t request_id)
     return nodenum;
 }
 
+// Back-calculate the real epoch for any queued packet still carrying a millis() rx_time
+// placeholder, now that the clock is trustworthy.
+void MeshService::reconcilePendingRxTimes()
+{
+    const uint32_t nowEpoch = getValidTime(RTCQualityFromNet);
+    if (nowEpoch == 0) // called before the clock was actually valid - nothing to reconcile against
+        return;
+    const uint32_t nowMillis = Time::getMillis();
+
+    // Rotate the queue once. TypedQueue is strictly FIFO on both backends, so dequeueing and
+    // re-enqueueing every element in turn leaves the delivery order unchanged.
+    for (int remaining = toPhoneQueue.numUsed(); remaining > 0; remaining--) {
+        meshtastic_MeshPacket *p = toPhoneQueue.dequeuePtr(0);
+        if (!p) // drained from under us - nothing left to rotate
+            break;
+        if (!p->has_rx_time) {
+            // Unsigned subtraction is wraparound-safe; rx_time is a 32-bit wire field, so the
+            // placeholder was never wider than 32 bits to begin with.
+            const uint32_t elapsedMs = nowMillis - p->rx_time;
+            p->rx_time = nowEpoch - (elapsedMs / 1000);
+            p->has_rx_time = true;
+        }
+        if (!toPhoneQueue.enqueue(p, 0)) { // mirrors sendToPhone()'s degrade-on-failure path
+            LOG_CRIT("Failed to requeue a packet into toPhoneQueue!");
+            releaseToPool(p);
+            fromNum++; // notify observers so the phone can resync
+        }
+    }
+}
+
 #if MESHTASTIC_ENABLE_FRAME_INJECTION
 // Deliver a client-supplied frame into the receive pipeline as if it arrived off the LoRa chip. Mirrors
 // the portduino SimRadio SIMULATOR_APP unwrap so the same host wire format works on real hardware: the
@@ -220,7 +251,9 @@ void MeshService::injectAsReceived(meshtastic_MeshPacket &p)
         mp->rx_rssi = -40;
         mp->has_rx_rssi = true;
     }
-    mp->rx_time = getValidTime(RTCQualityFromNet);
+    // dispatchReceived() restamps this when the packet re-enters the pipeline below; stamp it
+    // here anyway so the packet is never observable with an unset arrival time.
+    stampRxTime(mp);
     LOG_INFO("inject: RX from=0x%08x to=0x%08x id=0x%08x ch=%d %s", mp->from, mp->to, mp->id, mp->channel,
              mp->which_payload_variant == meshtastic_MeshPacket_encrypted_tag ? "encrypted" : "decoded");
     router->enqueueReceivedMessage(mp);
@@ -258,7 +291,8 @@ void MeshService::handleToRadio(meshtastic_MeshPacket &p)
     if (p.id == 0)
         p.id = generatePacketId(); // If the phone didn't supply one, then pick one
 
-    p.rx_time = getValidTime(RTCQualityFromNet); // Record the time the packet arrived from the phone
+    // Record the time the packet arrived from the phone.
+    stampRxTime(&p);
 
     IF_SCREEN(if (p.decoded.portnum == meshtastic_PortNum_TEXT_MESSAGE_APP && p.decoded.payload.size > 0 &&
                   p.to != NODENUM_BROADCAST && p.to != 0) // DM only
@@ -595,6 +629,11 @@ bool MeshService::isToPhoneQueueEmpty()
 
 uint32_t MeshService::GetTimeSinceMeshPacket(const meshtastic_MeshPacket *mp)
 {
+    // rx_time may be a millis() placeholder while has_rx_time is false - don't age it as
+    // wall-clock, and don't pass it off as "just now" either.
+    if (!mp->has_rx_time)
+        return SINCE_UNKNOWN;
+
     uint32_t now = getTime();
 
     uint32_t last_seen = mp->rx_time;

src/mesh/MeshService.cpp

@@ -137,6 +137,10 @@ class MeshService
     // search the queue for a request id and return the matching nodenum
     NodeNum getNodenumFromRequestId(uint32_t request_id);
 
+    // Rewrite any queued-for-phone packet still carrying a millis() rx_time placeholder into a
+    // real epoch, now that the wall clock is trustworthy.
+    void reconcilePendingRxTimes();
+
     // Release QueueStatus packet to pool
     void releaseQueueStatusToPool(meshtastic_QueueStatus *p) { queueStatusPool.release(p); }
 
@@ -205,6 +209,7 @@ class MeshService
 
     ErrorCode sendQueueStatusToPhone(const meshtastic_QueueStatus &qs, ErrorCode res, uint32_t mesh_packet_id);
 
+    /// Seconds since the packet arrived, or SINCE_UNKNOWN if it carries no trustworthy rx_time.
     uint32_t GetTimeSinceMeshPacket(const meshtastic_MeshPacket *mp);
 
   private:

src/mesh/MeshService.h

@@ -3237,6 +3237,11 @@ uint32_t sinceLastSeen(const meshtastic_NodeInfoLite *n)
 
 uint32_t sinceReceived(const meshtastic_MeshPacket *p)
 {
+    // rx_time may be a millis() placeholder while has_rx_time is false - don't age it as
+    // wall-clock, and don't pass it off as "just now" either.
+    if (!p->has_rx_time)
+        return SINCE_UNKNOWN;
+
     uint32_t now = getTime();
 
     int delta = (int)(now - p->rx_time);
@@ -3633,7 +3638,8 @@ void NodeDB::updateFrom(const meshtastic_MeshPacket &mp)
             return;
         }
 
-        if (mp.rx_time) // if the packet has a valid timestamp use it to update our last_heard
+        // Gate on has_rx_time, not truthiness - rx_time may hold a millis() placeholder.
+        if (mp.has_rx_time)
             info->last_heard = mp.rx_time;
 
         // Gate on the packet actually having been received over our own radio, not on rx_snr being

src/mesh/NodeDB.cpp

@@ -166,10 +166,15 @@ inline bool isRadioProfileFile(const char *filename)
            strcmp(filename, backupFileName) == 0;
 }
 
+/// "No trustworthy arrival time", as distinct from "zero seconds ago". Deliberately huge so the
+/// display formatters fall into their existing unknown-age branches ("unknown age" / "?").
+inline constexpr uint32_t SINCE_UNKNOWN = UINT32_MAX;
+
 /// Given a node, return how many seconds in the past (vs now) that we last heard from it
 uint32_t sinceLastSeen(const meshtastic_NodeInfoLite *n);
 
-/// Given a packet, return how many seconds in the past (vs now) it was received
+/// Given a packet, return how many seconds in the past (vs now) it was received,
+/// or SINCE_UNKNOWN if it carries no trustworthy rx_time.
 uint32_t sinceReceived(const meshtastic_MeshPacket *p);
 
 /// Outcome of mapping a single on-wire last-byte (next_hop / relay_node) back to a full NodeNum.

src/mesh/NodeDB.h

@@ -1238,6 +1238,17 @@ void setReplayHopFields(meshtastic_MeshPacket &pkt, const meshtastic_NodeInfoLit
     pkt.hop_limit = hopsAway < hopLimit ? (uint8_t)(hopLimit - hopsAway) : 0;
 }
 
+/// 2020-01-01: a boot-relative counter needs ~50 years of uptime to reach this, so it cannot be
+/// confused with a real epoch.
+constexpr uint32_t MIN_PLAUSIBLE_EPOCH = 1577836800u;
+
+/// Not every last_heard writer gates on RTC quality - NodeDB::addFromContact stamps it with a bare
+/// getTime(), which is boot-relative seconds on a node that has never had a clock.
+bool lastHeardIsWallClock(const meshtastic_NodeInfoLite *header)
+{
+    return header && header->last_heard >= MIN_PLAUSIBLE_EPOCH;
+}
+
 } // namespace
 
 // Replayed packets deliberately leave rx_rssi absent. NodeInfoLite stores no RSSI, and
@@ -1258,6 +1269,8 @@ meshtastic_MeshPacket PhoneAPI::makeReplayPositionPacket(NodeNum num, const mesh
     // fix time (which is often 0 and, when present, already round-trips inside the payload
     // via ConvertToPosition).
     pkt.rx_time = header ? header->last_heard : 0;
+    // Present only when last_heard is a genuine epoch - see lastHeardIsWallClock().
+    pkt.has_rx_time = lastHeardIsWallClock(header);
     // Stable per-node/per-fix id: replaying the same unchanged history on every
     // reconnect must not look like a brand new packet to the phone's history/dedup.
     pkt.id = makeReplayPacketId(num, pkt.rx_time, meshtastic_PortNum_POSITION_APP);
@@ -1285,6 +1298,8 @@ meshtastic_MeshPacket PhoneAPI::makeReplayTelemetryPacket(NodeNum num, const mes
     // No native timestamp on telemetry packets here; use last_heard.
     const meshtastic_NodeInfoLite *header = nodeDB->getMeshNode(num);
     pkt.rx_time = header ? header->last_heard : 0;
+    // Present only when last_heard is a genuine epoch - see lastHeardIsWallClock().
+    pkt.has_rx_time = lastHeardIsWallClock(header);
     pkt.id = makeReplayPacketId(num, pkt.rx_time, meshtastic_Telemetry_device_metrics_tag);
     pkt.channel = header ? header->channel : 0;
     pkt.rx_snr = header ? header->snr : 0;
@@ -1391,6 +1406,8 @@ meshtastic_MeshPacket PhoneAPI::makeReplayEnvironmentPacket(uint32_t num, const
     pkt.to = NODENUM_BROADCAST;
     const meshtastic_NodeInfoLite *header = nodeDB->getMeshNode(num);
     pkt.rx_time = header ? header->last_heard : 0;
+    // Present only when last_heard is a genuine epoch - see lastHeardIsWallClock().
+    pkt.has_rx_time = lastHeardIsWallClock(header);
     pkt.id = makeReplayPacketId(num, pkt.rx_time, meshtastic_Telemetry_environment_metrics_tag);
     pkt.channel = header ? header->channel : 0;
     pkt.rx_snr = header ? header->snr : 0;
@@ -1456,6 +1473,8 @@ meshtastic_MeshPacket PhoneAPI::makeReplayStatusPacket(uint32_t num, const mesht
     // StatusMessage has no native timestamp; use last_heard.
     const meshtastic_NodeInfoLite *header = nodeDB->getMeshNode(num);
     pkt.rx_time = header ? header->last_heard : 0;
+    // Present only when last_heard is a genuine epoch - see lastHeardIsWallClock().
+    pkt.has_rx_time = lastHeardIsWallClock(header);
     pkt.id = makeReplayPacketId(num, pkt.rx_time, meshtastic_PortNum_NODE_STATUS_APP);
     pkt.channel = header ? header->channel : 0;
     pkt.rx_snr = header ? header->snr : 0;

src/mesh/PhoneAPI.cpp

@@ -877,7 +877,7 @@ void printPacket(const char *prefix, const meshtastic_MeshPacket *p)
         out += DEBUG_PORT.mt_sprintf(" len=%d", p->encrypted.size + sizeof(PacketHeader));
     }
 
-    if (p->rx_time != 0)
+    if (p->has_rx_time) // rx_time has explicit presence; a millis() placeholder isn't a real reading to print
         out += DEBUG_PORT.mt_sprintf(" rxtime=%u", p->rx_time);
     if (p->rx_snr != 0.0)
         out += DEBUG_PORT.mt_sprintf(" rxSNR=%g", p->rx_snr);