fix(diagnostics): tell an empty system log apart from a device that never answered - #552
Conversation
…ever answered GetSystemLogAsync returned an empty list for two unrelated situations: the device answered and its log buffer is genuinely empty, and the device did not answer at all. A caller could not tell which -- so a silent link, a wedged text exchange, or an unsupported header on below-floor firmware all presented as "your log is empty". That is the least useful answer a DIAGNOSTICS call can give, because it is indistinguishable from a clean bill of health, on the one call an operator reaches for when they suspect the device is unwell. THE SIGNAL WAS ALREADY THERE. The firmware terminates every SYSTem:LOG? dump with a blank line whether or not it had anything to say -- measured on a bench Nq1 running 3.7.2 with a raw pyserial probe, three trials of three: an empty log answers b'\r\n' in 6 ms, a populated one answers its entries followed by the same trailing b'\r\n' (issue #543). Since #538 the exchange already parses that blank line internally; it filtered it out before any caller saw it. So ANY line reaching the diagnostics layer -- blank or not -- means the device answered, and zero lines means it did not. No extra command, and in particular no SYSTem:ERRor? pairing, which would pop an entry off the device's error queue as a side effect of a read. WHY A PARAMETER RATHER THAN A NEW SEAM. keepBlankLines is threaded through the existing ExecuteTextCommandAsync rather than added as a parallel method, which is the convention this seam already documents: "a parallel method would be bypassed silently by any subclass that overrides only this one ... Overriders must widen their signature -- a compile error, which is the point." That is most of this diff: 22 test doubles gain one parameter. It also happens to be load-bearing rather than incidental -- the diagnostics tests inject their canned responses by overriding that virtual, so a new seam would bypass their injection entirely and the behaviour could not be unit-tested at all. A TEST THAT ENCODED THE WRONG BELIEF. GetSystemLogAsync_WhenBufferEmpty_ReturnsEmpty canned NOTHING and asserted no-throw, commented "No lines = genuinely empty buffer (firmware writes nothing)". That premise is false, and it is exactly what made the two states indistinguishable. It now cans a blank line, which is what the device actually sends, and two cases join it: zero lines throws, and a populated dump does not leak its terminator into the parsed entries as a phantom log line. Baseline-checked rather than assumed: main fails 4 tests here before any change (Device.Discovery.LinuxUsbPortDescriptorProviderTests, a WSL/Windows runtime artefact). After this change: the same 4, with passing tests up from 3531 to 3533. Fixes #543
|
/improve |
|
/agentic_review |
PR Summary by QodoDistinguish empty system logs from unresponsive devices
AI Description
Diagram
High-Level Assessment
Files changed (20)
|
PR Code Suggestions ✨Warning
No code suggestions found for the PR. |
I mutation-tested the three tests added for #543 instead of assuming they earned their place, and one did not. GetSystemLogAsync_WhenBufferHasEntries_IgnoresTheTerminator asserted that a populated dump does not leak its trailing blank line into the parsed entries. Removing the filter it was meant to guard changes nothing: the test still passes. SystemLogParser.Parse ignores blank lines, and ScpiResponseClassifier.IsErrorOnlyResponse skips them explicitly via IsNullOrWhiteSpace, so the terminator could never have become an entry whether the filter ran or not. That makes it an assertion that cannot fail. Removed rather than left in to look like coverage. The other two are load-bearing and proven so: WhenDeviceAnswersNothingAtAll_Throws fails against the pre-change implementation -- it is what the fix is for. WhenBufferEmpty_ReturnsEmpty passes before AND after, so it is a guard rather than a proof, but it is a real guard: mutating the throw to fire when every line is blank (rather than when no line arrived) makes it fail, which is the over-eager fix it exists to prevent. The filter itself stays, with its comment corrected to say it is belt and braces rather than implying it is load-bearing. It keeps the seam's contract -- everything downstream sees the same content lines it saw before keepBlankLines existed -- true by construction instead of by depending on two other components' internals.
Mutation-tested my own tests, and removed one that could not failRather than assume the three new tests earned their place, I mutated both the pre-change implementation and the fix to see which assertions actually move.
The removed one asserted something that was never possible. It checked that a populated dump does not leak its trailing blank line into the parsed entries. But The second one is a guard, not a proof, and I checked it is a real guard. It passes before and after, so it does not demonstrate the fix — but mutating the throw from "no line arrived" to "every line is blank" makes it fail. That is exactly the over-eager version of this fix (throwing on a healthy device whose log is simply empty), so the test is worth its place. Consequence for the filter itself: Revised counts: 4 pre-existing failures unchanged, passing 3531 → 3532, total 3537 → 3538. This is the same check I asked the adversarial audit to run as item (d). It found it first. |
Code Review by Qodo
1. Late terminator masks silence
|
![qodo-code-review[bot]](https://avatars.githubusercontent.com/in/484649?s=60&v=4){kind=small}
| result = (keepBlankLines | ||
| ? afterStale | ||
| : afterStale.Where(line => line.Length > 0)) |
There was a problem hiding this comment.
1. Late terminator masks silence 🐞 Bug ☼ Reliability
A blank line arriving after staleLineCount is captured but before the new command is sent is retained as the current response, so GetSystemLogAsync bypasses its no-answer exception and reports an empty log for a silent command. This violates the new diagnostic distinction in a timing-dependent stale-response case.
Agent Prompt
## Issue description
A delayed blank terminator from an earlier exchange can arrive after the stale-line snapshot but before the current command is sent. Because `keepBlankLines` now preserves that line, diagnostics treats it as proof that the current `SYSTem:LOG?` answered and returns an empty log even when the new command receives no response.
## Issue Context
The consumer callback appends concurrently. The stale boundary is captured immediately before invoking the setup/send callback, leaving a window in which old input is classified as current input. Strengthen the pre-command drain/boundary mechanism so input attributable to an earlier exchange cannot satisfy the current exchange; preserve immediate legitimate replies from the newly sent command.
## Fix Focus Areas
- src/Daqifi.Core/Device/Internal/TextExchangeEngine.cs[418-466]
- src/Daqifi.Core/Device/Internal/TextExchangeEngine.cs[478-510]
- src/Daqifi.Core/Device/Internal/TextExchangeEngine.cs[538-561]
- src/Daqifi.Core.Tests/Device/DaqifiDeviceStaleTextLineTests.cs[1-430]
ⓘ Copy this prompt and use it to remediate the issue with your preferred AI generation tools
Adversarial audit:
|
| check | result |
|---|---|
| adversarial audit | PASS, treadmill: false, 1 raw finding / 1 refuted / 0 confirmed |
/improve |
0 suggestions |
/agentic_review |
1 bug, refuted above and tracked as #553 |
| tests | 4 pre-existing failures (unchanged), passing 3531 → 3532 |
| tests that earn their place | 1 fails on pre-change code; 1 guard proven by mutating the fix; 1 removed as vacuous |
Merging.
1 participant
Fixes #543.
The defect
GetSystemLogAsyncreturned an empty list for two unrelated situations:A caller could not tell which. So a silent link, a wedged text exchange, or an unsupported header on below-floor firmware all presented as "your log is empty" — the least useful answer a diagnostics call can give, because it is indistinguishable from a clean bill of health, on the one call an operator reaches for when they suspect the device is unwell.
The signal was already there
The firmware terminates every
SYSTem:LOG?dump with a blank line, whether or not it had anything to say. From #543's bench work (Nq1 on firmware 3.7.2, raw pyserial probe, no Core in the path, three trials of three):Since #538 the exchange already parses that blank line internally — it just filtered it out before any caller saw it. So any line reaching the diagnostics layer means the device answered, and zero lines means it did not.
No extra command, and specifically no
SYSTem:ERRor?pairing, which would pop an entry off the device's error queue as a side effect of a read — a poor thing for a diagnostics call to do whenGetSystemErrorCountAsyncsits on the same interface.Why a parameter and not a new method
keepBlankLinesis threaded through the existingExecuteTextCommandAsyncrather than added as a parallel method — the convention this seam already documents:That is most of this diff: 22 test doubles gain one parameter. It is also load-bearing rather than incidental — the diagnostics tests inject their canned responses by overriding that virtual, so a new seam would bypass their injection and the behaviour could not be unit-tested at all. I checked
ExecuteRawCaptureAsyncas an alternative first; using it would mean reimplementing line reading, timeouts and consumer swapping in the diagnostics op, which is worse.Only the
Actionoverload is widened — the 8 overrides of the async overload are untouched.A test that encoded the wrong belief
GetSystemLogAsync_WhenBufferEmpty_ReturnsEmptycanned nothing and asserted no-throw, commented "No lines = genuinely empty buffer (firmware writes nothing)".That premise is false, and it is precisely what made the two states indistinguishable — the test asserted the ambiguity as correct. It now cans a blank line, which is what the device actually sends, and two cases join it:
WhenBufferEmpty_ReturnsEmptyWhenDeviceAnswersNothingAtAll_ThrowsDeviceDiagnosticsExceptionnaming the conditionWhenBufferHasEntries_IgnoresTheTerminatorBehaviour change — worth a release note
A caller polling the log on a flaky link previously got an empty list and now gets a throw. That is the point of the issue, but it is visible. The exception is a
DeviceDiagnosticsException(not a new type), socatchblocks that already handle diagnostics failures keep working.Test plan
mainfails 4 tests on this station before any change — allDevice.Discovery.LinuxUsbPortDescriptorProviderTests, a WSL/Windows runtime artefact, not related to this work.Daqifi.Mcp.Testsbuilds clean (itsDeviceDoubleis one of the widened doubles).The issue's open questions, answered: it is scoped to
SYSTem:LOG?only.GetCommandHistoryAsyncis untouched — it has a "No command history" marker and is already distinguishable, exactly as the issue suspected.🤖 Generated with Claude Code