vcontact race fix

zephcore/app/CompanionMesh.cpp

@@ -219,6 +219,9 @@ CompanionMesh::CompanionMesh(mesh::Radio &radio, mesh::MillisecondClock &ms, mes
 	memset(_vcontact_pending, 0, sizeof(_vcontact_pending));
 	_vcontact_pending_count = 0;
 	_vcontact_hold_msgwait = false;
+	_vcontact_hold_expiry = 0;
+	_last_msgwait_ms = 0;
+	_last_sync_req_ms = 0;
 	_vcontact_app_hidden = false;
 	_vcontact_confirm_ack = 0;
 	_vcontact_confirm_work.self = this;
@@ -602,6 +605,95 @@ void CompanionMesh::confirmOfflineMessage()
 	_offline_queue_count--;
 }
 
+/* How long CMD_APP_START may suppress v-contact notice prompts.
+ *
+ * This deadline is also the worst-case freeze a mid-session CMD_APP_START can
+ * impose, because the app is under no obligation to follow one with the
+ * message sync that clears the latch — so it must be short enough that nobody
+ * notices, not merely short enough to recover eventually.
+ *
+ * It only has to cover the handoff between CMD_APP_START and the
+ * CMD_GET_CONTACTS that normally follows it, which is where a prompt could
+ * make the app fetch a message from a contact it has not been told about yet.
+ * The dump itself is gated directly by _contact_iter_active below, for however
+ * long it takes, and once the dump is done a prompt is harmless. Measured on
+ * hardware, a full 350-contact initial sync runs APP_START to
+ * PACKET_NO_MORE_MSGS in ~2.9 s, so the handoff is a small fraction of that.
+ *
+ * History, because the sizing is the whole bug: 60 s produced the ~54 s
+ * "v-contact is frozen" reports. 10 s only looked fixed — hardware logs showed
+ * the user's own settings-screen-to-message time landing at 10.5-11.7 s, so
+ * the latch was expiring inline microseconds before the prompt and the feature
+ * was winning a race by half a second. Do not raise this to "be safe"; raising
+ * it re-creates the bug, and the thing it guards does not need the time. */
+#define VCONTACT_HOLD_MAX_MS 3000
+
+bool CompanionMesh::vcontactMsgWaitHeld()
+{
+	/* A live contact dump is the concrete hazard the hold exists for: a
+	 * MSG_WAITING mid-dump makes the app interleave message-sync into the
+	 * contact stream, which trips the "reset iterator on any other command"
+	 * guard and truncates the sync. Checked directly rather than inferred from
+	 * the latch, so the deadline below can be short without ever exposing a
+	 * slow dump. */
+	if (_contact_iter_active) {
+		return true;
+	}
+	if (!_vcontact_hold_msgwait) {
+		return false;
+	}
+	if (_vcontact_hold_expiry && _ms->getMillis() >= _vcontact_hold_expiry) {
+		LOG_WRN("vcontact: msgwait hold expired without a completed sync");
+		_vcontact_hold_msgwait = false;
+		_vcontact_hold_expiry = 0;
+		return false;
+	}
+	return true;
+}
+
+void CompanionMesh::pushMsgWaiting()
+{
+	_last_msgwait_ms = _ms->getMillis();
+	LOG_INF("msgwait: prompting app, %d queued", _offline_queue_count);
+	sendPush(PUSH_CODE_MSG_WAITING);
+}
+
+/* Re-prompt cadence.
+ *
+ * Observed on hardware: the app ignores the first MSG_WAITING after a settings
+ * write (the GPS toggle) but honours a later identical one, so the reply is
+ * recovered rather than lost — it just arrives one cadence late. At the
+ * original 15 s that was a ~20 s wait with the 5 s housekeeping granularity on
+ * top, which reads as broken even though nothing is. The prompt is a 1-byte
+ * idempotent frame, so the cost of asking again sooner is nil, and the 5 s tick
+ * puts the real floor here anyway: 4 s means the first re-prompt lands on the
+ * first tick at least 4 s after the original, i.e. 4-5 s. */
+#define MSGWAIT_REPROMPT_MS 4000
+
+void CompanionMesh::msgWaitingWatchdog()
+{
+	if (_offline_queue_count == 0) {
+		return;
+	}
+	/* Inside the initial-sync window or a live contact dump — the sync itself
+	 * will drain the queue, and prompting now would truncate it. Both cases
+	 * live in vcontactMsgWaitHeld(); the dump has its own stall watchdog and
+	 * _last_sync_req_ms covers an active message drain, so nothing is stranded
+	 * by waiting here. */
+	if (vcontactMsgWaitHeld()) {
+		return;
+	}
+	int64_t now = _ms->getMillis();
+	int64_t last = (_last_sync_req_ms > _last_msgwait_ms) ? _last_sync_req_ms
+							      : _last_msgwait_ms;
+	if (now - last < MSGWAIT_REPROMPT_MS) {
+		return;
+	}
+	LOG_WRN("msgwait watchdog: %d queued, app quiet for %ds, re-prompting",
+		_offline_queue_count, (int)((now - last) / 1000));
+	pushMsgWaiting();
+}
+
 bool CompanionMesh::continueContactIteration()
 {
 	if (!_contact_iter_active) return false;
@@ -835,7 +927,7 @@ void CompanionMesh::onMessageRecv(const ContactInfo &contact, mesh::Packet *pkt,
 
 	markConnectionActive(contact);
 	queueContactMessage(contact, pkt, TXT_TYPE_PLAIN, sender_timestamp, nullptr, 0, text);
-	sendPush(PUSH_CODE_MSG_WAITING);
+	pushMsgWaiting();
 #if ZEPHCORE_HAS_UI_TASK
 	notify_contact_msg_ui(contact, pkt, text, _offline_queue_count);
 #endif
@@ -1003,8 +1095,12 @@ void CompanionMesh::vcontactQueueText(const char *text)
 	 * prompting for messages from a contact the app just dropped is noise. The
 	 * messages stay in the offline queue and drain on the next connect, when
 	 * the contact is back. */
-	if (!_vcontact_hold_msgwait && !_vcontact_app_hidden) {
-		sendPush(PUSH_CODE_MSG_WAITING);
+	if (!vcontactMsgWaitHeld() && !_vcontact_app_hidden) {
+		pushMsgWaiting();
+	} else {
+		LOG_INF("msgwait: suppressed (hold=%d hidden=%d), %d queued",
+			(int)_vcontact_hold_msgwait, (int)_vcontact_app_hidden,
+			_offline_queue_count);
 	}
 }
 
@@ -1444,7 +1540,7 @@ void CompanionMesh::queueLocalSentContactMessage(const ContactInfo &contact,
 
 	LOG_DBG("queueLocalSentContactMessage: frame_len=%d delivered=%d", i, (int)delivered);
 	queueOfflineMessage(frame, i);
-	sendPush(PUSH_CODE_MSG_WAITING);
+	pushMsgWaiting();
 }
 
 void CompanionMesh::queueLocalSentChannelMessage(uint8_t channel_idx,
@@ -1490,7 +1586,7 @@ void CompanionMesh::queueLocalSentChannelMessage(uint8_t channel_idx,
 	LOG_DBG("queueLocalSentChannelMessage: frame_len=%d channel_idx=%d heard=%d",
 		i, channel_idx, (int)heard_repeat);
 	queueOfflineMessage(frame, i);
-	sendPush(PUSH_CODE_MSG_WAITING);
+	pushMsgWaiting();
 }
 
 void CompanionMesh::onCommandDataRecv(const ContactInfo &contact, mesh::Packet *pkt,
@@ -1501,7 +1597,7 @@ void CompanionMesh::onCommandDataRecv(const ContactInfo &contact, mesh::Packet *
 
 	markConnectionActive(contact);
 	queueContactMessage(contact, pkt, TXT_TYPE_CLI_DATA, sender_timestamp, nullptr, 0, text);
-	sendPush(PUSH_CODE_MSG_WAITING);
+	pushMsgWaiting();
 	{
 		struct ui_joystick_cli_data cli = { text };
 		ui_notify_joystick_event(UI_JOYSTICK_CLI_RESPONSE, contact.id.pub_key, &cli);
@@ -1518,7 +1614,7 @@ void CompanionMesh::onSignedMessageRecv(const ContactInfo &contact, mesh::Packet
 	markContactsDirty();
 	// sender_prefix is 4 bytes
 	queueContactMessage(contact, pkt, TXT_TYPE_SIGNED_PLAIN, sender_timestamp, sender_prefix, 4, text);
-	sendPush(PUSH_CODE_MSG_WAITING);
+	pushMsgWaiting();
 #if ZEPHCORE_HAS_UI_TASK
 	notify_contact_msg_ui(contact, pkt, text, _offline_queue_count);
 #endif
@@ -1588,7 +1684,7 @@ void CompanionMesh::onChannelMessageRecv(const mesh::GroupChannel &channel, mesh
 
 	LOG_DBG("onChannelMessageRecv: frame_len=%d channel_idx=%d", i, channel_idx);
 	queueOfflineMessage(frame, i);
-	sendPush(PUSH_CODE_MSG_WAITING);
+	pushMsgWaiting();
 #if ZEPHCORE_HAS_UI_TASK
 	{
 		ChannelDetails ch;
@@ -1633,7 +1729,7 @@ void CompanionMesh::onChannelDataRecv(const mesh::GroupChannel &channel, mesh::P
 	LOG_DBG("onChannelDataRecv: frame_len=%d channel_idx=%d data_type=%d",
 		i, channel_idx, (int)data_type);
 	queueOfflineMessage(frame, i);
-	sendPush(PUSH_CODE_MSG_WAITING);
+	pushMsgWaiting();
 }
 
 int CompanionMesh::appendSelfTelemetry(uint8_t *reply, uint8_t permissions)
@@ -2264,6 +2360,7 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len)
 			sendPacketError(ERR_ILLEGAL_ARG);
 			return true;
 		}
+		LOG_INF("CMD_APP_START: session reset, %d queued", _offline_queue_count);
 		// Reset per-session state for a fresh app session. BLE/USB also run
 		// this cleanup on disconnect, but the serial transport has no
 		// disconnect event, so APP_START is its authoritative session-reset
@@ -2282,8 +2379,11 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len)
 		k_work_cancel_delayable(&_vcontact_confirm_work.work);
 
 		/* New session: suppress v-contact notice MSG_WAITING until the initial
-		 * sync (contacts + messages) completes at PACKET_NO_MORE_MSGS. */
+		 * sync (contacts + messages) completes at PACKET_NO_MORE_MSGS, or the
+		 * deadline expires — see _vcontact_hold_expiry for why the latch needs
+		 * a second exit. */
 		_vcontact_hold_msgwait = true;
+		_vcontact_hold_expiry = _ms->getMillis() + VCONTACT_HOLD_MAX_MS;
 		/* An app-side delete only hides the v-contact for the session it
 		 * happened in — this is that session boundary, so it comes back. */
 		_vcontact_app_hidden = false;
@@ -2755,6 +2855,11 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len)
 		LOG_DBG("CMD_SYNC_NEXT_MESSAGE: queue_count=%d pending=%d",
 			_offline_queue_count, _sync_pending);
 
+		/* The app is draining — hold the watchdog off for another window. */
+		_last_sync_req_ms = _ms->getMillis();
+		LOG_INF("msgwait: app asked for next msg, %d queued",
+			_offline_queue_count);
+
 		/* Phone asking for next = implicit ACK for the previously-peeked message */
 		if (_sync_pending) {
 			confirmOfflineMessage();
@@ -2788,8 +2893,9 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len)
 			 * the window was just drained by this message-sync; if one raced in
 			 * after the last peek, prompt for it now. */
 			_vcontact_hold_msgwait = false;
+			_vcontact_hold_expiry = 0;
 			if (_offline_queue_count > 0) {
-				sendPush(PUSH_CODE_MSG_WAITING);
+				pushMsgWaiting();
 			}
 		}
 		return true;

zephcore/app/CompanionMesh.h

@@ -211,6 +211,23 @@ public:
 	/** Dump progress cursor — the watchdog re-kicks only if this stops moving. */
 	int getContactIterIdx() const { return _contact_iter_idx; }
 
+	/**
+	 * Offline-queue stall watchdog — call from the housekeeping tick.
+	 *
+	 * A queued message reaches the app through exactly one best-effort
+	 * PUSH_CODE_MSG_WAITING, which the app answers with CMD_SYNC_NEXT_MESSAGE.
+	 * Nothing retried that push: if it was dropped (BLE congestion) or
+	 * suppressed (_vcontact_hold_msgwait), or the app simply ignored it because
+	 * it believed a sync was already running, the queue sat untouched until the
+	 * next connect — the app showed a delivered message with no reply, then
+	 * received the whole backlog at once on reconnect. The contact dump and
+	 * advertising both already have a watchdog here; the message queue did not.
+	 *
+	 * MSG_WAITING is one of the three genuinely idempotent push codes (see
+	 * zephcore_ble_send's overflow note), so a duplicate prompt costs nothing.
+	 */
+	void msgWaitingWatchdog();
+
 	/**
 	 * Cancel pending message sync. Un-ACKed message stays in queue.
 	 * Call on BLE disconnect so the message is re-sent on reconnect.
@@ -529,8 +546,32 @@ private:
 	 * CMD_SET_DEVICE_TIME) it makes the app interleave message-sync into the
 	 * contact stream, which trips the "reset iterator on any other command"
 	 * guard and truncates the sync. Held from CMD_APP_START until the first
-	 * PACKET_NO_MORE_MSGS (end of the contacts+messages initial sync). */
+	 * PACKET_NO_MORE_MSGS (end of the contacts+messages initial sync).
+	 *
+	 * Bounded by _vcontact_hold_expiry. PACKET_NO_MORE_MSGS used to be the only
+	 * exit, and the app is not obliged to produce it: a session that set the
+	 * latch and then never message-synced to empty kept it forever, so every
+	 * later CLI reply, battery alert and notice queued silently and the user
+	 * saw the backlog only on reconnect. Confirmed on hardware — the app
+	 * re-issues CMD_APP_START when its device-settings screen opens, about 4 s
+	 * before the GPS toggle that appeared to cause it, on a connection already
+	 * hours old and long past its initial sync.
+	 *
+	 * The real hazard (a prompt landing mid contact-dump) is checked directly
+	 * in vcontactMsgWaitHeld(), so this latch is now only the CMD_APP_START ->
+	 * CMD_GET_CONTACTS handoff guard and its deadline is sized accordingly.
+	 * See VCONTACT_HOLD_MAX_MS. */
 	bool _vcontact_hold_msgwait;
+	int64_t _vcontact_hold_expiry;   /* _ms->getMillis() deadline for the latch */
+	/** Read the latch, expiring it first. Use instead of touching the flag. */
+	bool vcontactMsgWaitHeld();
+	/* Offline-queue stall watchdog state, both _ms->getMillis(). The watchdog
+	 * re-prompts only once the later of the two has gone quiet. */
+	int64_t _last_msgwait_ms;   /* last PUSH_CODE_MSG_WAITING we emitted */
+	int64_t _last_sync_req_ms;  /* last CMD_SYNC_NEXT_MESSAGE the app sent */
+	/** Emit PUSH_CODE_MSG_WAITING and stamp the watchdog. Every prompt goes
+	 *  through here so the watchdog cannot fire on top of a live sync. */
+	void pushMsgWaiting();
 	/* App-side delete (CMD_REMOVE_CONTACT for the loopback key) hides the
 	 * v-contact for the rest of the session only — it deliberately does NOT
 	 * touch prefs.v_contact_enabled. The v-contact is an ordinary entry in the

zephcore/src/main_companion.cpp

@@ -371,20 +371,26 @@ static void retry_pending_reply(void)
  * Push notification callback - sends push frames to BLE.
  * Push frames have format: [push_code] [data...]
  */
+/* True when a binary companion client is actually listening.
+ *
+ * A USB companion session is "connected" too, but zephcore_ble_is_connected()
+ * only reports the BLE link — without the USB check, pushes (new messages,
+ * etc.) are silently dropped on a USB-attached client.  A text-CLI session is
+ * not a binary companion, so V3 frames must not go to it. */
+static bool companion_transport_up(void)
+{
+	bool up = zephcore_ble_is_connected();
+#if ZEPHCORE_USB_STACK
+	up = up || (zephcore_ble_get_active_iface() == ZEPHCORE_IFACE_USB &&
+		    !zephcore_usb_companion_is_text_session());
+#endif
+	return up;
+}
+
 static void push_callback(uint8_t code, const uint8_t *data, size_t len)
 {
-	/* No point serializing if nobody is listening. A USB companion session
-	 * is "connected" too, but zephcore_ble_is_connected() only reports the BLE
-	 * link — without the USB check, pushes (new messages, etc.) are silently
-	 * dropped on a USB-attached client. */
-	bool transport_up = zephcore_ble_is_connected();
-#if ZEPHCORE_USB_STACK
-	/* A text-CLI session is not a binary companion — don't push V3 frames to it. */
-	transport_up = transport_up ||
-		(zephcore_ble_get_active_iface() == ZEPHCORE_IFACE_USB &&
-		 !zephcore_usb_companion_is_text_session());
-#endif
-	if (!transport_up) return;
+	/* No point serializing if nobody is listening. */
+	if (!companion_transport_up()) return;
 
 	/* Push frame: code byte + optional data */
 	uint8_t push_buf[1 + MAX_FRAME_SIZE - 1];
@@ -599,6 +605,24 @@ static void mesh_event_loop(void)
 				wd_last_iter_idx = -1;
 			}
 
+			/* Offline-queue stall watchdog — the queue is drained
+			 * solely by the app answering a single best-effort
+			 * MSG_WAITING push, so one dropped or suppressed prompt
+			 * strands every queued message until the next connect
+			 * (the "v-contact replies only arrive on reconnect"
+			 * failure). Same shape as the contact-dump watchdog
+			 * above: self-throttled, re-prompts only after the app
+			 * has gone quiet.
+			 *
+			 * Gated on a live client: prompting into a dead link
+			 * accomplishes nothing, spams the log every cycle, and
+			 * burns the re-prompt timer so the first prompt after a
+			 * reconnect would be late. A reconnect drains the queue
+			 * through the initial sync anyway. */
+			if (companion_mesh_ptr && companion_transport_up()) {
+				companion_mesh_ptr->msgWaitingWatchdog();
+			}
+
 			/* BLE advertising watchdog — if bt_le_adv_start failed
 			 * transiently (HCI timeout, controller pacing) the device
 			 * would silently stop advertising and be undiscoverable