Improve timesync acquisition and logging

- Add boot acquisition mode with wider RX windows until first TimeSync
- Log sender TimeSync RX results and receiver TX events
- Document acquisition behavior

README.md

@@ -307,6 +307,7 @@ inline constexpr uint16_t EXPECTED_SENDER_IDS[NUM_SENDERS] = { 0xF19C };
 - If a sender’s timestamps drift from receiver time by more than `TIME_SYNC_DRIFT_THRESHOLD_SEC`, the receiver enters a burst mode (every `TIME_SYNC_BURST_INTERVAL_MS` for `TIME_SYNC_BURST_DURATION_MS`).
 - Sender raises a local `TimeSync` error if it has not received a time beacon for `TIME_SYNC_ERROR_TIMEOUT_MS` (default 2 days). This is shown on the sender OLED only and is not sent over LoRa.
 - RTC loads are validated (reject out-of-range epochs) so LoRa TimeSync can recover if the RTC is wrong.
+- Sender uses a short “fast acquisition” mode on boot (until first LoRa TimeSync) with wider RX windows to avoid phase-miss.
 
 ## Build Environments
 - `lilygo-t3-v1-6-1`: production build (debug on)

src/main.cpp

@@ -104,10 +104,14 @@ static uint32_t g_sender_last_timesync_check_ms = 0;
 static uint32_t g_sender_rx_window_ms = 0;
 static uint32_t g_sender_sleep_ms = 0;
 static uint32_t g_sender_power_log_ms = 0;
+static uint8_t g_sender_timesync_mode = 0;
 static MeterData g_last_meter_data = {};
 static bool g_last_meter_valid = false;
 static uint32_t g_last_meter_rx_ms = 0;
 static uint32_t g_meter_stale_seconds = 0;
+static constexpr uint32_t SENDER_TIMESYNC_ACQUIRE_MS = 10UL * 60UL * 1000UL;
+static constexpr uint32_t SENDER_TIMESYNC_ACQUIRE_INTERVAL_SEC = 20;
+static constexpr uint32_t SENDER_TIMESYNC_ACQUIRE_WINDOW_MS = 3000;
 
 static void watchdog_kick();
 
@@ -123,6 +127,17 @@ static void serial_debug_printf(const char *fmt, ...) {
   Serial.println(buf);
 }
 
+static void sender_set_timesync_mode(uint8_t mode) {
+  if (g_sender_timesync_mode == mode) {
+    return;
+  }
+  g_sender_timesync_mode = mode;
+  if (SERIAL_DEBUG_MODE) {
+    const char *label = mode == 2 ? "acquire" : (mode == 1 ? "slow" : "fast");
+    serial_debug_printf("timesync: mode=%s", label);
+  }
+}
+
 static uint16_t g_last_batch_id_rx[NUM_SENDERS] = {};
 
 struct BatchRxState {
@@ -170,11 +185,18 @@ static bool battery_sample_due(uint32_t now_ms) {
 
 static bool sender_timesync_window_due() {
   uint32_t interval_sec = SENDER_TIMESYNC_CHECK_SEC_FAST;
+  bool in_acquire = (g_sender_last_timesync_rx_ms == 0) && (millis() - g_boot_ms < SENDER_TIMESYNC_ACQUIRE_MS);
   bool allow_slow = (millis() - g_boot_ms >= 60000UL) && time_is_synced() && time_rtc_present() &&
       (g_sender_last_timesync_rx_ms > 0);
   // RTC boot time is not evidence of receiving network TimeSync.
-  if (allow_slow) {
+  if (in_acquire) {
+    interval_sec = SENDER_TIMESYNC_ACQUIRE_INTERVAL_SEC;
+    sender_set_timesync_mode(2);
+  } else if (allow_slow) {
     interval_sec = SENDER_TIMESYNC_CHECK_SEC_SLOW;
+    sender_set_timesync_mode(1);
+  } else {
+    sender_set_timesync_mode(0);
   }
   static uint32_t last_interval_sec = 0;
   if (last_interval_sec != interval_sec) {
@@ -837,7 +859,8 @@ static void sender_loop() {
   if (timesync_due) {
     LoraPacket rx = {};
     uint32_t rx_start = millis();
-    bool got = lora_receive_window(rx, SENDER_TIMESYNC_WINDOW_MS);
+    uint32_t window_ms = (g_sender_timesync_mode == 2) ? SENDER_TIMESYNC_ACQUIRE_WINDOW_MS : SENDER_TIMESYNC_WINDOW_MS;
+    bool got = lora_receive_window(rx, window_ms);
     uint32_t rx_elapsed = millis() - rx_start;
     if (SERIAL_DEBUG_MODE) {
       g_sender_rx_window_ms += rx_elapsed;
@@ -849,7 +872,10 @@ static void sender_loop() {
           g_sender_timesync_error = false;
           display_set_last_error(FaultType::None, 0, 0);
         }
+        serial_debug_printf("timesync: rx ok window_ms=%lu", static_cast<unsigned long>(window_ms));
       }
+    } else if (SERIAL_DEBUG_MODE) {
+      serial_debug_printf("timesync: rx miss window_ms=%lu", static_cast<unsigned long>(window_ms));
     }
   }
   uint32_t timesync_age_ms = (g_sender_last_timesync_rx_ms > 0) ? (now_ms - g_sender_last_timesync_rx_ms)
@@ -1079,6 +1105,9 @@ static void receiver_loop() {
         note_fault(g_receiver_faults, g_receiver_last_error, g_receiver_last_error_utc, g_receiver_last_error_ms, FaultType::LoraTx);
         display_set_last_error(g_receiver_last_error, g_receiver_last_error_utc, g_receiver_last_error_ms);
       }
+      if (SERIAL_DEBUG_MODE) {
+        serial_debug_printf("timesync: tx burst");
+      }
       g_last_timesync_ms = now_ms;
     } else if (now_ms - g_last_timesync_ms > interval_sec * 1000UL) {
       g_last_timesync_ms = now_ms;
@@ -1086,6 +1115,9 @@ static void receiver_loop() {
         note_fault(g_receiver_faults, g_receiver_last_error, g_receiver_last_error_utc, g_receiver_last_error_ms, FaultType::LoraTx);
         display_set_last_error(g_receiver_last_error, g_receiver_last_error_utc, g_receiver_last_error_ms);
       }
+      if (SERIAL_DEBUG_MODE) {
+        serial_debug_printf("timesync: tx normal");
+      }
     }
   }