Merge pull request #126 from MrAlders0n/copilot/add-debug-logging-standards-again

Refactor ping/repeat flow: 10s RX window + async API posting

Author: MrAlders0n

content/wardrive.js

@@ -44,7 +44,7 @@ const STATUS_UPDATE_DELAY_MS = 100;            // Brief delay to ensure "Ping se
 const MAP_REFRESH_DELAY_MS = 1000;             // Delay after API post to ensure backend updated
 const MIN_PAUSE_THRESHOLD_MS = 1000;           // Minimum timer value (1 second) to pause
 const MAX_REASONABLE_TIMER_MS = 5 * 60 * 1000; // Maximum reasonable timer value (5 minutes) to handle clock skew
-const RX_LOG_LISTEN_WINDOW_MS = 7000;          // Listen window for repeater echoes (7 seconds)
+const RX_LOG_LISTEN_WINDOW_MS = 10000;         // Listen window for repeater echoes (10 seconds)
 
 // Pre-computed channel hash and key for the wardriving channel
 // These will be computed once at startup and used for message correlation and decryption
@@ -1322,6 +1322,47 @@ async function postToMeshMapperAPI(lat, lon, heardRepeats) {
   }
 }
 
+/**
+ * Post to MeshMapper API in background (non-blocking)
+ * This function runs asynchronously after the RX listening window completes
+ * UI status messages are suppressed for successful posts, errors are shown
+ * @param {number} lat - Latitude
+ * @param {number} lon - Longitude
+ * @param {number} accuracy - GPS accuracy in meters
+ * @param {string} heardRepeats - Heard repeats string (e.g., "4e(1.75),b7(-0.75)" or "None")
+ */
+async function postApiInBackground(lat, lon, accuracy, heardRepeats) {
+  debugLog(`postApiInBackground called with heard_repeats="${heardRepeats}"`);
+  
+  // Hidden 3-second delay before API POST (no user-facing status message)
+  debugLog("Starting 3-second delay before API POST");
+  await new Promise(resolve => setTimeout(resolve, 3000));
+  
+  debugLog("3-second delay complete, posting to API");
+  try {
+    await postToMeshMapperAPI(lat, lon, heardRepeats);
+    debugLog("Background API post completed successfully");
+    // No success status message - suppress from UI
+  } catch (error) {
+    debugError("Background API post failed:", error);
+    // Errors are propagated to caller for user notification
+    throw error;
+  }
+  
+  // Update map after API post
+  debugLog("Scheduling coverage map refresh");
+  setTimeout(() => {
+    const shouldRefreshMap = accuracy && accuracy < GPS_ACCURACY_THRESHOLD_M;
+    
+    if (shouldRefreshMap) {
+      debugLog(`Refreshing coverage map (accuracy ${accuracy}m within threshold)`);
+      scheduleCoverageRefresh(lat, lon);
+    } else {
+      debugLog(`Skipping map refresh (accuracy ${accuracy}m exceeds threshold)`);
+    }
+  }, MAP_REFRESH_DELAY_MS);
+}
+
 /**
  * Post to MeshMapper API and refresh coverage map after heard repeats are finalized
  * This executes immediately (no delay) because it's called after the RX listening window
@@ -2712,7 +2753,7 @@ async function sendPing(manual = false) {
 
     const ch = await ensureChannel();
 
-    // Capture GPS coordinates at ping time - these will be used for API post after 7s delay
+    // Capture GPS coordinates at ping time - these will be used for API post after 10s delay
     state.capturedPingCoords = { lat, lon, accuracy };
     debugLog(`GPS coordinates captured at ping time: lat=${lat.toFixed(5)}, lon=${lon.toFixed(5)}, accuracy=${accuracy}m`);
 
@@ -2750,7 +2791,7 @@ async function sendPing(manual = false) {
       startRxListeningCountdown(RX_LOG_LISTEN_WINDOW_MS);
     }
 
-    // Schedule the sequence: listen for 7s, THEN finalize repeats and post to API
+    // Schedule the sequence: listen for 10s, THEN finalize repeats and background the API post
     // This timeout is stored in meshMapperTimer for cleanup purposes
     // Capture coordinates locally to prevent race conditions with concurrent pings
     const capturedCoords = state.capturedPingCoords;
@@ -2771,26 +2812,44 @@ async function sendPing(manual = false) {
       const heardRepeatsStr = formatRepeaterTelemetry(repeaters);
       debugLog(`Formatted heard_repeats for API: "${heardRepeatsStr}"`);
 
+      // Update status and start next timer IMMEDIATELY (before API post)
+      // This is the key change: we don't wait for API to complete
+      if (state.connection) {
+        if (state.running) {
+          // Check if we should resume a paused auto countdown (manual ping during auto mode)
+          const resumed = resumeAutoCountdown();
+          if (!resumed) {
+            // No paused timer to resume, schedule new auto ping (this was an auto ping)
+            debugLog("Scheduling next auto ping immediately after RX window");
+            scheduleNextAutoPing();
+          } else {
+            debugLog("Resumed auto countdown after manual ping");
+          }
+        } else {
+          debugLog("Setting dynamic status to Idle (manual mode)");
+          setDynamicStatus("Idle");
+        }
+      }
+      
+      // Unlock ping controls immediately (don't wait for API)
+      unlockPingControls("after RX listening window completion");
+      
+      // Background the API posting (runs asynchronously, doesn't block)
       // Use captured coordinates for API post (not current GPS position)
       if (capturedCoords) {
         const { lat: apiLat, lon: apiLon, accuracy: apiAccuracy } = capturedCoords;
-        debugLog(`Using captured ping coordinates for API post: lat=${apiLat.toFixed(5)}, lon=${apiLon.toFixed(5)}, accuracy=${apiAccuracy}m`);
+        debugLog(`Backgrounding API post for coordinates: lat=${apiLat.toFixed(5)}, lon=${apiLon.toFixed(5)}, accuracy=${apiAccuracy}m`);
 
-        // Post to API with heard repeats data
-        await postApiAndRefreshMap(apiLat, apiLon, apiAccuracy, heardRepeatsStr);
+        // Post to API in background (async, fire-and-forget with error handling)
+        postApiInBackground(apiLat, apiLon, apiAccuracy, heardRepeatsStr).catch(error => {
+          debugError(`Background API post failed: ${error.message}`, error);
+          // Show error to user only if API fails
+          setDynamicStatus("Error: API post failed", STATUS_COLORS.error);
+        });
       } else {
         // This should never happen as coordinates are always captured before ping
         debugError(`CRITICAL: No captured ping coordinates available for API post - this indicates a logic error`);
         debugError(`Skipping API post to avoid posting incorrect coordinates`);
-        
-        // Unlock ping controls since API post is being skipped
-        unlockPingControls("after skipping API post due to missing coordinates");
-        
-        // Fix 2: Schedule next auto ping if in auto mode to prevent getting stuck
-        if (state.running && !state.autoTimerId) {
-          debugLog("Scheduling next auto ping after skipped API post");
-          scheduleNextAutoPing();
-        }
       }
 
       // Clear timer reference

docs/CONNECTION_WORKFLOW.md

@@ -313,14 +313,15 @@ When a wardriving slot is revoked during an active session (detected during API
 **Revocation Sequence:**
 
 1. **Detection**
-   - During "Posting to API" operation
+   - During background API POST operation (runs asynchronously after RX window)
    - API returns `{"allowed": false, ...}`
    - Detected in `postToMeshMapperAPI()` response handler
 
 2. **Initial Status**
    - **Dynamic Status**: `"Error: Posting to API (Revoked)"` (red)
    - Sets `state.disconnectReason = "slot_revoked"`
    - Visible for 1.5 seconds
+   - **Note**: User may already be seeing "Idle" or "Waiting for next ping" before this error appears (because API runs in background)
 
 3. **Disconnect Initiated**
    - Calls `disconnect()` after 1.5s delay
@@ -334,16 +335,23 @@ When a wardriving slot is revoked during an active session (detected during API
    - **Dynamic Status**: `"WarDriving slot has been revoked"` (red, terminal - NO "Disconnected:" prefix)
    - This is the final terminal status
 
-**Complete Revocation Flow:**
+**Complete Revocation Flow (Updated for background API posting):**
 ```
 Connection Status: (unchanged) → "Disconnecting" → "Disconnected"
-Dynamic Status: "Posting to API" → "Error: Posting to API (Revoked)" → "—" → "WarDriving slot has been revoked"
+Dynamic Status: "Idle"/"Waiting for next ping" → "Error: Posting to API (Revoked)" → "—" → "WarDriving slot has been revoked"
 ```
+**Timeline:**
+- T+0s: RX window completes, status shows "Idle" or "Waiting for next ping", next timer starts
+- T+0-3s: Background API post running (3s delay, then POST) - silent
+- T+3-4s: Revocation detected, "Error: Posting to API (Revoked)" shown (1.5s)
+- T+4.5s: Disconnect initiated
+- T+5s: Terminal status "WarDriving slot has been revoked"
 
 **Key Differences from Normal Disconnect:**
 - Normal disconnect: Dynamic Status shows `"—"` (em dash)
 - Revocation: Dynamic Status shows `"WarDriving slot has been revoked"` (red error, no prefix)
 - Revocation shows intermediate "Error: Posting to API (Revoked)" state
+- With the new ping/repeat flow, revocation may be detected after user already sees "Idle" or "Waiting for next ping" (because API runs in background)
 
 ## Workflow Diagrams
 
@@ -590,6 +598,120 @@ stateDiagram-v2
 - Error → Disconnected
 - Recovery always possible
 
+## Ping/Repeat Listener Flow
+
+### Overview
+
+The ping/repeat listener flow manages the complete lifecycle of a wardrive ping operation, from sending the ping to listening for repeater echoes to posting data to the MeshMapper API.
+
+**Key Design Change (v1.4.2+):** API posting now runs in the background (asynchronously) to prevent blocking the main ping cycle. This allows the next ping timer to start immediately after the RX listening window completes, without waiting for the API POST to finish.
+
+### New Ping/Repeat Flow (v1.4.2+)
+
+```
+┌─────────────────────────────────────────────────────────────────────┐
+│ 1. Ping Sent                                                        │
+│    - Send ping to mesh network                                      │
+│    - Start repeater echo tracking                                   │
+│    - Show "Ping sent" status                                        │
+│    - Lock ping controls                                             │
+└──────────────────────────────┬──────────────────────────────────────┘
+                               │
+                               ▼
+┌─────────────────────────────────────────────────────────────────────┐
+│ 2. RX Listening Window (10 seconds)                                 │
+│    - Listen for repeater echoes                                     │
+│    - Show "Listening for heard repeats (Xs)" countdown              │
+│    - Track all repeaters that forward the ping                      │
+│    - Update session log in real-time                                │
+└──────────────────────────────┬──────────────────────────────────────┘
+                               │
+                               ▼
+┌─────────────────────────────────────────────────────────────────────┐
+│ 3. RX Window Complete - IMMEDIATE ACTIONS                           │
+│    - Stop RX listening countdown                                    │
+│    - Finalize heard repeats (stop tracking)                         │
+│    - Update UI log with final repeater data                         │
+│    - **Unlock ping controls** ← NEW: Don't wait for API             │
+│    - **Start next ping timer** ← NEW: Don't wait for API            │
+│    - **Set status to "Idle"/"Waiting for next ping"**               │
+└──────────────────────────────┬──────────────────────────────────────┘
+                               │
+                               ▼
+┌─────────────────────────────────────────────────────────────────────┐
+│ 4. Background API Posting (Async, Non-Blocking)                     │
+│    - Delay 3 seconds (silent, no status message)                    │
+│    - POST ping data to MeshMapper API                               │
+│    - **Success**: Silent (no UI notification)                       │
+│    - **Error**: Show "Error: API post failed"                       │
+│    - Refresh coverage map after POST completes                      │
+└─────────────────────────────────────────────────────────────────────┘
+```
+
+### Key Changes from Previous Flow (v1.4.1 and earlier)
+
+**Old Flow:**
+1. Ping sent
+2. Listen for repeats (7 seconds)
+3. **Wait for API post to complete** (3s delay + POST time)
+4. **Then** unlock controls and start next timer
+5. Status: "Ping sent" → "Listening (7s)" → "Posting to API" → "Idle"/"Waiting"
+
+**New Flow:**
+1. Ping sent
+2. Listen for repeats (10 seconds) ← **Increased from 7s to 10s**
+3. **Immediately** unlock controls and start next timer ← **Key change**
+4. **Background** API post (silent on success, error only if fails)
+5. Status: "Ping sent" → "Listening (10s)" → "Idle"/"Waiting" ← **No "Posting to API"**
+
+### Benefits
+
+1. **Faster cycle times**: Next ping can start immediately after 10s RX window, not waiting for API
+2. **Better UX**: User sees smooth progression without API delays blocking the UI
+3. **More repeater data**: 10-second listen window (vs 7s) captures more mesh echoes
+4. **Cleaner UI**: API success messages suppressed, only errors shown
+5. **Non-blocking**: API failures don't stall the ping cycle
+
+### Implementation Details
+
+**Functions:**
+- `postApiInBackground(lat, lon, accuracy, heardRepeats)` - New async function for background API posting
+- `sendPing(manual)` - Refactored to start next timer immediately after RX window
+- `RX_LOG_LISTEN_WINDOW_MS` - Increased from 7000ms to 10000ms
+
+**Error Handling:**
+- API POST failures are caught with `.catch()` handler
+- Error message shown to user: "Error: API post failed"
+- Main ping cycle continues unaffected by API failures
+- Background failures don't crash or stall the application
+
+**Debug Logging:**
+- `[DEBUG] Backgrounding API post for coordinates: ...`
+- `[DEBUG] Starting 3-second delay before API POST`
+- `[DEBUG] 3-second delay complete, posting to API`
+- `[DEBUG] Background API post completed successfully`
+- `[DEBUG] Background API post failed: ...`
+
+### Status Message Behavior
+
+**Visible to User:**
+- "Ping sent" (500ms minimum)
+- "Listening for heard repeats (10s)" (countdown, 10 seconds)
+- "Idle" or "Waiting for next ping (Xs)" (immediately after RX window)
+- "Error: API post failed" (only if background API fails)
+
+**Not Visible (Suppressed):**
+- ~~"Posting to API"~~ - No longer shown for successful API posts
+- API success confirmation - Silent operation
+
+### Timing Analysis
+
+**Total time from ping to next ping (Auto mode, 30s interval):**
+- Old flow: 10s (ping) + 7s (listen) + 3s (delay) + 0.5s (API) + 30s (interval) = ~50.5s between pings
+- New flow: 10s (ping) + 10s (listen) + 30s (interval) = ~50s between pings (API runs in parallel)
+
+**Actual improvement:** Next timer starts ~3.5s earlier (no waiting for API), better responsiveness
+
 ## Passive RX Log Listening
 
 ### Overview