fix(device): reject a stale blank line in a text exchange's capture-to-send window - #591
Conversation
…'s command is still being sent TextExchangeEngine.ExecuteAsync captured its stale-line boundary before setupActionAsync ran, so a late reply to an earlier command landing in the sub-millisecond gap between the capture and the send completing was still counted as this exchange's answer. Ordinary content is left on the wider boundary (narrowing it risks discarding a genuinely fast reply), but a blank line captured in that gap is now dropped: a device cannot emit a terminator for a command it has not yet been sent, so any blank there is necessarily a leftover from an earlier exchange. That matters most for SYSTem:LOG?, which reads "any line arrived" as "the device answered" — a stale blank in that window would otherwise report an empty log for a device that had gone silent. The prior attempt at this fix (recorded on #553) was reverted because the existing access-counted mock transport can only release a line before or at the consumer bind, both of which land before the boundary is even captured — it could not reach the real window. This adds a narrow test-only hook, ITextExchangeHost.OnStaleLineBoundaryCaptured (a no-op on the real device), fired at the boundary itself, so a test double can release a line into the transport at that exact instant and pair it with a deliberately slow setup action to guarantee the line arrives before the send completes. Fixes #553.
|
/agentic_review |
PR Summary by QodoDrop stale blank lines that arrive between boundary capture and command send
AI Description
Diagram
High-Level Assessment
Files changed (5)
|
Code Review by Qodo
1. Boundary captured before send
|
Qodo review round 1 correctly noted setupActionAsync returning only means the command was enqueued to MessageProducer, not that its background thread has written it yet. Tried closing that gap by reusing DrainOutboundQueueAsync (the same bounded IsIdle wait already used before the swap) right after setupActionAsync, before capturing the boundary. Bench-verified on a real Nq1 and reverted: the drain call itself measured under 15ms, but with it in place the device's actual reply was then reliably delayed by roughly two seconds — 9/9 runs slow with the drain enabled (2.6-3.1s round trip vs. a 0.6-1.1s baseline), 6/6 fast with it disabled, isolated by toggling only that one call with debug logging on. The cause didn't resolve within the scope of this fix, and trading a measured ~2.5x regression on every text exchange for a theoretical, low-severity race is the wrong trade. Left a comment recording this so a future attempt starts from the finding instead of rediscovering it.
|
Re: "Boundary captured before send" (Qodo review round 1, finding 1, Low/Weak) — investigated, and deliberately not adopting the suggested fix. Explained in 5913940. The point is correct: Bench-tested it against a real Nq1 before deciding, since this is the most order-sensitive code in the device. Isolated by toggling only that one call with debug logging on:
So the extra wait itself isn't slow; something about issuing it causes the device to answer roughly two seconds later, consistently and reproducibly. I couldn't isolate the root cause within the scope of this fix. Trading a measured ~2.5x latency regression on every text exchange for a theoretical, Low-severity race that the finding itself flags as weak relevance is the wrong trade, so I reverted the drain and the test for it, keeping only a comment recording the investigation for whoever revisits this. Not resolving this thread — it's a comment, not an inline review thread — but flagging that it's addressed via the commit above. |
|
/agentic_review |
|
Code review by qodo was updated up to the latest commit 5913940 |
The previous note attributed the outbound-drain experiment's slowdown to the device replying ~2s later "for a cause that did not resolve within the scope of this fix". Bench-tested against a real Nq1 on /dev/cu.usbmodem1101 while reviewing this PR, and that is a misdiagnosis of our own data: there is no device delay. The device answers on time, and both effects the drain produced are ours. Draining first is not a stricter version of this boundary, it is an inversion of it. The device answers ~6ms after the write, faster than the drain's own 10ms poll tick, so the genuine SYSTem:LOG? terminator lands on the far side of the boundary and the filter below discards it as stale. GetSystemLogAsync then throws "the device did not answer" for a device that answered, 10/10 runs. The boundary is safe because it is strictly earlier than any possible reply, not because it is precise about the write. Recorded as #593. The ~2-2.5x slowdown is the wait loop below, which infers "the device answered" from a count increase observed inside the loop and so cannot see a line that landed before its first poll — the exchange then sits out the full responseTimeoutMs. Recorded as #592. Seeding it from staleLineCount restores full speed with the drain still in place (1058ms vs 1056ms), which is what isolates the cause to the engine rather than the firmware. Comment-only; no behavior change. Suite: 3726 passed, 0 failed. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Summary
TextExchangeEngine.ExecuteAsync's stale-line boundary was captured beforesetupActionAsyncran, so a late reply to an earlier exchange landing in the sub-millisecond gap between the capture and the send completing was still counted as this exchange's answer.SYSTem:LOG?(added in fix(diagnostics): tell an empty system log apart from a device that never answered #552), which reads "any line arrived" as "the device answered" — a stale blank there would otherwise report an empty log for a device that had gone silent.ITextExchangeHost.OnStaleLineBoundaryCaptured(a no-op on the real device), fired at the boundary capture point, so a test double can release a line into the transport at that exact instant. The previous attempt at this fix (recorded on TextExchangeEngine's stale-line boundary is captured before the send, so a late reply can still be attributed to the wrong exchange #553) was reverted because the existing access-counted mock transport can't reach that window — both of its hookableStreamaccesses land before the boundary is even captured.Test plan
ExecuteTextCommand_DropsABlankThatArrivesWhileTheCommandIsStillBeingSent) fails without the fix (verified by reverting the engine change locally and re-running: exactly 1 failure) and passes with it.ExecuteTextCommand_KeepsAContentLineThatArrivesWhileTheCommandIsStillBeingSent) documents that content lines are deliberately left alone.Daqifi.Core.Testssuite: 3726 passed, 0 failed.SYSTem:LOG?(x3) andSYSTem:LOG:CLEarstill round-trip correctly through the changed engine.Fixes #553.