feat(voice): trace VMP receive lifecycle

This commit is contained in:
liu weikai
2026-08-10 14:57:40 +08:00
parent 0c6068ecee
commit 7e2bf56fe6
3 changed files with 119 additions and 1 deletions
+54 -1
View File
@@ -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.
@@ -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;
}
@@ -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<unsigned long>(candidate_control_.sender_id),
static_cast<unsigned>(candidate_control_.conversation_channel),
static_cast<unsigned>(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<unsigned long>(incoming_control_.sender_id),
static_cast<unsigned>(incoming_control_.conversation_channel),
static_cast<unsigned>(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<unsigned long>(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<unsigned long>(kReceiveWindowMs));
receivePublicMedia();
setActive(false);
releaseRadio();
@@ -1433,10 +1451,15 @@ class PagerReceiveSession final
else if (ready_sent && static_cast<std::size_t>(packet_len) == vmp::kPrivateShardFrameSize &&
handlePrivateShard())
{
Serial.printf("[VMP][RX] private media complete unique_shards=%u\n",
static_cast<unsigned>(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<unsigned>(media_->receive_block.receivedShardCount()));
}
void receivePublicMedia()
@@ -1457,10 +1480,14 @@ class PagerReceiveSession final
if (static_cast<std::size_t>(packet_len) == vmp::kPublicShardFrameSize &&
handlePublicShard())
{
Serial.printf("[VMP][RX] broadcast media complete unique_shards=%u\n",
static_cast<unsigned>(media_->receive_block.receivedShardCount()));
return;
}
(void)radio::startReceive(&radio_lease_);
}
Serial.printf("[VMP][RX] broadcast media timeout unique_shards=%u\n",
static_cast<unsigned>(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<unsigned>(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<unsigned>(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<unsigned>(header.shard_index),
static_cast<unsigned>(media_->receive_block.receivedShardCount()));
}
return false;
}
Serial.printf("[VMP][RX] shard quorum reached unique_shards=%u; recover\n",
static_cast<unsigned>(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())