From 7e2bf56fe600440dee23af8380ae6385d45883df Mon Sep 17 00:00:00 2001 From: liu weikai Date: Mon, 10 Aug 2026 14:57:40 +0800 Subject: [PATCH] feat(voice): trace VMP receive lifecycle --- docs/design/lr1121_voice_message_protocol.md | 55 ++++++++++++++++++- ...st_vmp_attachment_persistence_contract.cpp | 23 ++++++++ .../src/voice/vmp_pager_session.cpp | 42 ++++++++++++++ 3 files changed, 119 insertions(+), 1 deletion(-) diff --git a/docs/design/lr1121_voice_message_protocol.md b/docs/design/lr1121_voice_message_protocol.md index d6110592..110a4dca 100644 --- a/docs/design/lr1121_voice_message_protocol.md +++ b/docs/design/lr1121_voice_message_protocol.md @@ -478,7 +478,60 @@ No delivery receipt is added to V1 because receiving one would require another r Completed automated gates in this workspace are the Pager release build, clang-format 14, ESP stack-hygiene validation, and the MT MQTT/LXMF local-only ingress contract tests. RF and audio behavior still require the two-device hardware gates above before a production-default rollout. -## 14. Open engineering decisions retained for field validation +## 14. Two-Pager hardware acceptance and log capture + +This gate is deliberately a **two-device** procedure. A successful build, a UI +render, or a single Pager's local `Sent` state is not evidence that the +LR1121/Sub-GHz/2.4 GHz handoff works. Use two LR1121 Pagers with compatible +region settings, distinct node IDs, the same selected logical chat channel, +and a verified private-contact secret for the private cases. Capture both +115200-baud serial logs from boot to the end of every case. Do not put voice +content, contact secrets, or full ciphertext into a bug report; the VMP +session and local IDs are enough to correlate the two logs. + +| Case | Operator steps | Sender evidence | Receiver evidence | Pass condition | +| --- | --- | --- | --- | --- | +| Short push-to-talk | In one private conversation, press microphone for 0.5--2 s, then release. | UI immediately shows `REC`, then returns to the timeline. Logs include `hold begin accepted`, `capture begin`, `hold release`, `local message committed ... delivery=sending`; the exact row changes to `Sent` or `Failed`. | None is required until the RF portion begins. | No `Voice session ...` toast is used as the primary flow; exactly one outgoing durable row is created. | +| Five-second cap | Keep microphone pressed past 5.0 s. | UI reaches `REC 5.0/5`, exits capture without another press, and logs `capture end ... elapsed_ms=5000` followed by one local-message commit. | Same as the applicable delivery case. | Capture ends once, never creates a second send on release, and never exceeds the media limit. | +| Private direct RF | Speak 1--3 s in a verified private conversation. | Ordered log spine: `private offer tx`, `private accept authenticated`, `private ready_probe attempt`, `private ready authenticated`, `shard_train complete`, `outbound end sent=1`, and `local delivery committed ... state=Sent`. | Ordered log spine: `private offer accepted`, `private accept sent`, `private 2g rx ready`, `private ready sent`, authenticated/accepted shards, `shard quorum reached`, then `inbox durable_commit`. The private voice appears only in this exact protocol/channel/peer conversation. | Receiver can tap and hear the clip; no payload is forwarded, retransmitted, or injected into MT/MC/RT traffic. | +| Private unavailable / timeout | Turn the receiving Pager off, or make its verified contact unavailable, then send. | The outgoing row remains the same object and ends `Failed`; log contains `private accept failed_or_timed_out` and `outbound end sent=0` followed by a durable delivery-state update. | No receiver row exists. | No duplicate outgoing row, no infinite retry, and normal Sub-GHz RX resumes. | +| Broadcast direct RF | Send from the channel/group conversation while one or more compatible Pagers listen. | Log includes `broadcast announce sent`, zero or more `broadcast ready_probe sent`, `shard_train complete`, and local row `Sent`. | Receiver sends no VMP response. It logs `broadcast announce accepted`, `broadcast 2g rx ready`, accepted shards, `shard quorum reached`, and `inbox durable_commit`; the row is public/source-unverified in the originating broadcast conversation. | Sender does not wait for a receipt and no receiver emits ACK/NACK/READY/rebroadcast traffic. | +| No first media | Cause a private or broadcast announcement/readiness exchange but prevent the ten data frames. | Sender may show `Failed` only for its local send failure; it must restore Sub-GHz RX. | After five seconds receiver logs `private media timeout ready=... unique_shards=0` or `broadcast media timeout unique_shards=0`, and creates no playable row. | A `READY_PROBE` alone is never rendered as a voice message. | +| Playback ownership | Tap a received row, then tap another row while the first is playing. | UI logs `playback queued`; Pager logs `[VMP][PLAY] begin` then `[VMP][PLAY] end`. | Same if tested on the receiver. | The first row changes to `Playing voice...` then resets; a concurrent request is rejected only with `Voice audio is busy`, without RF or storage changes. | +| Closed-thread unread and restart | Receive a clip while its bound conversation is closed; inspect list, reboot, then reopen that conversation. | N/A. | List displays `Voice message` preview and unread count. After reboot, log shows `attachment inbox restore=...`; opening the exact conversation logs `conversation_read` and clears only its incoming unread state. | The clip remains ordered correctly, playable, and absent from all other protocol/channel/peer threads. | + +For the log reviewer, these correlation points are normative: + +1. An outgoing `local message committed ... delivery=sending` MUST precede a + carrier attempt, so the sender has an IM row even if no receiver is present. +2. An incoming `inbox durable_commit` MUST precede the chat projection log + `stage=apply_voice`; a failed durable commit must roll back instead of + displaying a non-persistent received message. +3. A private test must show both `private accept authenticated` and `private + ready authenticated` before `shard_train complete`. The `ACCEPT` proves the + target reserved 2.4 GHz; `READY` proves it is actually listening before + the first voice frame. +4. A broadcast test MUST NOT contain a receiver-side VMP transmit log. The + expected receiver operation is validate, store, display, and optionally + play only. +5. After every terminal result, send and receive logs must show the normal + Sub-GHz receive path restored. A failed VMP test must never strand the + device in a 2.4 GHz or radio-busy state. + +The following bounded log prefixes make an end-to-end capture searchable: + +```text +[ChatCompose][VMP] UI press/release dispatch +[ChatUiTrace][VMP] message projection, list refresh, read state, playback request +[VMP][AUDIO] capture timing and bounded Codec2 result +[VMP][TX] durable local row, carrier choice, terminal send state +[VMP][RF] Sub-GHz negotiation, 2.4 GHz readiness, shard train +[VMP][RX] receive validation and durable inbox commit +[VMP][PLAY] on-demand decode/playback lifecycle +[VMP][MQTT] isolated SX1262/LR1121 MQTT carrier plan only +``` + +## 15. Open engineering decisions retained for field validation * The exact region-specific 2.4 GHz channel whitelist and maximum EIRP must come from board RF compliance validation, not a universal firmware constant. * Profile `0x01` bitrate/deviation/bandwidth must be confirmed against the exact RadioLib LR1121 driver version and the Pager's matching network. A lower-rate fallback may be added behind the same profile registry. diff --git a/modules/core_chat/tests/test_vmp_attachment_persistence_contract.cpp b/modules/core_chat/tests/test_vmp_attachment_persistence_contract.cpp index b7cb2966..6423a06a 100644 --- a/modules/core_chat/tests/test_vmp_attachment_persistence_contract.cpp +++ b/modules/core_chat/tests/test_vmp_attachment_persistence_contract.cpp @@ -192,5 +192,28 @@ int main(int argc, char** argv) assert(pager_header.find("SX1262 never has a") != std::string::npos); assert(pager_audio.find("#if defined(ARDUINO_T_LORA_PAGER)") != std::string::npos); + + // An RF capture must be diagnosable from *both* Pagers. Keep the ingress, + // readiness, shard/FEC, and timeout spine explicit so an on-device report + // can distinguish a missing offer, 2.4 GHz setup failure, ready-probe + // failure, no-first-media condition, or durable-store failure. + assert(session.find("[VMP][RX] private offer accepted") != std::string::npos); + assert(session.find("[VMP][RX] private accept sent; switch_2g_rx") != + std::string::npos); + assert(session.find("[VMP][RX] private 2g rx ready window_ms=") != + std::string::npos); + assert(session.find("[VMP][RX] private ready sent; wait_first_voice") != + std::string::npos); + assert(session.find("[VMP][RX] private media timeout ready=") != + std::string::npos); + assert(session.find("[VMP][RX] broadcast announce accepted") != + std::string::npos); + assert(session.find("[VMP][RX] broadcast 2g rx ready window_ms=") != + std::string::npos); + assert(session.find("[VMP][RX] broadcast media timeout unique_shards=") != + std::string::npos); + assert(session.find("[VMP][RX] shard quorum reached unique_shards=") != + std::string::npos); + assert(session.find("[VMP][RX] inbox durable_commit") != std::string::npos); return 0; } diff --git a/platform/esp/arduino_common/src/voice/vmp_pager_session.cpp b/platform/esp/arduino_common/src/voice/vmp_pager_session.cpp index 8c66d9fb..228422ac 100644 --- a/platform/esp/arduino_common/src/voice/vmp_pager_session.cpp +++ b/platform/esp/arduino_common/src/voice/vmp_pager_session.cpp @@ -739,6 +739,10 @@ class PagerReceiveSession final { return; } + Serial.printf("[VMP][RX] private offer accepted source=%08lX channel=%u media_bytes=%u\n", + static_cast(candidate_control_.sender_id), + static_cast(candidate_control_.conversation_channel), + static_cast(candidate_control_.encoded_media_len)); handlePrivateOffer(envelope.bytes); return; } @@ -749,6 +753,10 @@ class PagerReceiveSession final envelope.bytes, sizeof(envelope.bytes), &incoming_control_) && tryBeginInbound()) { + Serial.printf("[VMP][RX] broadcast announce accepted source=%08lX channel=%u media_bytes=%u\n", + static_cast(incoming_control_.sender_id), + static_cast(incoming_control_.conversation_channel), + static_cast(incoming_control_.encoded_media_len)); receiveBroadcast(); } } @@ -1335,6 +1343,7 @@ class PagerReceiveSession final &session_keys_) || !prepareReceiveBlock()) { + Serial.printf("[VMP][RX] private offer rejected reason=auth_key_or_fec_prepare\n"); resetEphemeralState(); setActive(false); return; @@ -1358,22 +1367,27 @@ class PagerReceiveSession final !radio::tryAcquire(&radio_lease_) || !radio::transmit(&radio_lease_, control_wire_, control_len)) { + Serial.printf("[VMP][RX] private accept tx failed\n"); releaseRadio(); resetEphemeralState(); setActive(false); return; } + Serial.printf("[VMP][RX] private accept sent; switch_2g_rx\n"); radio::PhyProfile profile{}; if (!profileFor(incoming_control_, &profile) || !radio::switchTo2Ghz(&radio_lease_, profile) || !radio::startReceive(&radio_lease_)) { + Serial.printf("[VMP][RX] private 2g rx setup failed\n"); releaseRadio(); resetEphemeralState(); setActive(false); return; } + Serial.printf("[VMP][RX] private 2g rx ready window_ms=%lu\n", + static_cast(kReceiveWindowMs)); receivePrivateMedia(); setActive(false); releaseRadio(); @@ -1384,6 +1398,7 @@ class PagerReceiveSession final { if (!prepareReceiveBlock()) { + Serial.printf("[VMP][RX] broadcast announce rejected reason=fec_prepare\n"); setActive(false); return; } @@ -1393,10 +1408,13 @@ class PagerReceiveSession final !radio::switchTo2Ghz(&radio_lease_, profile) || !radio::startReceive(&radio_lease_)) { + Serial.printf("[VMP][RX] broadcast 2g rx setup failed\n"); releaseRadio(); setActive(false); return; } + Serial.printf("[VMP][RX] broadcast 2g rx ready window_ms=%lu\n", + static_cast(kReceiveWindowMs)); receivePublicMedia(); setActive(false); releaseRadio(); @@ -1433,10 +1451,15 @@ class PagerReceiveSession final else if (ready_sent && static_cast(packet_len) == vmp::kPrivateShardFrameSize && handlePrivateShard()) { + Serial.printf("[VMP][RX] private media complete unique_shards=%u\n", + static_cast(media_->receive_block.receivedShardCount())); return; } (void)radio::startReceive(&radio_lease_); } + Serial.printf("[VMP][RX] private media timeout ready=%u unique_shards=%u\n", + ready_sent ? 1U : 0U, + static_cast(media_->receive_block.receivedShardCount())); } void receivePublicMedia() @@ -1457,10 +1480,14 @@ class PagerReceiveSession final if (static_cast(packet_len) == vmp::kPublicShardFrameSize && handlePublicShard()) { + Serial.printf("[VMP][RX] broadcast media complete unique_shards=%u\n", + static_cast(media_->receive_block.receivedShardCount())); return; } (void)radio::startReceive(&radio_lease_); } + Serial.printf("[VMP][RX] broadcast media timeout unique_shards=%u\n", + static_cast(media_->receive_block.receivedShardCount())); } void handlePrivateReadyProbe(bool* ready_sent) @@ -1491,9 +1518,11 @@ class PagerReceiveSession final data_wire_, ready_len + vmp::kPrivateDataAuthTagSize)) { + Serial.printf("[VMP][RX] private ready tx failed\n"); return; } *ready_sent = true; + Serial.printf("[VMP][RX] private ready sent; wait_first_voice\n"); } bool handlePrivateShard() @@ -1512,6 +1541,8 @@ class PagerReceiveSession final { return false; } + Serial.printf("[VMP][RX] private shard authenticated index=%u\n", + static_cast(data_header_.shard_index)); return acceptShardAndStore(data_header_, shard_plaintext_); } @@ -1526,6 +1557,8 @@ class PagerReceiveSession final { return false; } + Serial.printf("[VMP][RX] broadcast shard valid index=%u\n", + static_cast(data_header_.shard_index)); return acceptShardAndStore(data_header_, shard); } @@ -1535,13 +1568,22 @@ class PagerReceiveSession final header, shard, vmp::kMaxShardPayloadSize); if (result != vmp::ReceiveBlockResult::Complete) { + if (result == vmp::ReceiveBlockResult::Accepted) + { + Serial.printf("[VMP][RX] shard accepted index=%u unique_shards=%u\n", + static_cast(header.shard_index), + static_cast(media_->receive_block.receivedShardCount())); + } return false; } + Serial.printf("[VMP][RX] shard quorum reached unique_shards=%u; recover\n", + static_cast(media_->receive_block.receivedShardCount())); std::size_t media_len = 0U; if (!media_->receive_block.recover(media_->received_media, sizeof(media_->received_media), &media_len)) { + Serial.printf("[VMP][RX] shard recovery failed\n"); return false; } if (!lockState())