Skip to content

Report command completion timeouts and recover the transport - #103

Open
hangzqcom wants to merge 8 commits into
developfrom
fix/tac-command-timeout
Open

hangzqcom wants to merge 8 commits into
developfrom
fix/tac-command-timeout

Conversation

@hangzqcom

@hangzqcom hangzqcom commented Oct 1, 2026 •

Copy link
Copy Markdown
Contributor

Summary

Device commands could report success even when the command never completed. This happened when the communication port was not actually open, or when a device did not acknowledge a queued command within the completion timeout.

This change makes command completion status observable, and adds an automatic recovery attempt so that a device which has stopped responding can be brought back without restarting the application.

Issue

The completion wait detected a timeout, logged it, and then cleared the same internal state used to represent successful completion. The wait function returned no status, so callers could not distinguish a completed command from a timed-out command.

The result was discarded at every layer of the command path:

  • The completion wait returned no status.
  • Device transport command handlers returned no status.
  • The device command layer assumed success once a command name was resolved.
  • The exported API therefore returned a success code for commands that never reached the hardware.

Queued multi-step command sequences had the same problem. They were treated as successful as soon as they were queued, without waiting for or validating completion.

A common trigger is a port that could not be opened, for example because another process already holds it. Opening the device correctly reported a failure, but if an application continued issuing commands anyway, those commands were queued against a port that was never usable and still returned success. An automation script could receive a success result for an operation such as a power or boot-mode request while the device state never changed, and the problem would only surface later through unrelated symptoms.

A second trigger is a debug board that stops acknowledging mid-session, for example after an unexpected USB re-enumeration. In that state every subsequent command times out, and reopening the device handle does not help because the underlying transport object is still the same unusable instance.

Fix Direction

Completion status is propagated through the command stack rather than discarded:

  • Completion waits return true for completion and false for timeout.
  • All device transport implementations propagate the result for pin-state commands.
  • The device abstraction converts a timeout into a structured command-timeout exception.
  • Queued command sequences now wait for completion and report a timeout failure.
  • A missing transport path now reports an explicit device-inactive error instead of silently returning.
  • The exported C API converts the timeout into a documented result code instead of allowing an exception to escape the ABI boundary.
  • The Python binding exposes the new result code and message.

A timed-out command now triggers one transport recovery attempt before failing:

  • The transport is torn down and reinitialized the same way it is set up at startup: stale protocol state is discarded, the device is given time to settle, the port is reopened, and the board identification handshake is completed before the transport is considered usable again.
  • Recovery is reported as successful only when the device has actually responded. A reopened but silent port is reported as a failure, so the result reflects the device rather than the file handle.
  • The command is then retried once. A persistent failure surfaces to the caller as a timeout rather than looping or stalling.
  • Recovery is attempted again on a later command if the device stops responding again.

Recovery runs on the thread that owns the transport. QSerialPort and the FTDI handles must only be used from their owning thread, and the drive thread reads and writes them continuously, so the requesting thread posts a request and waits for the drive thread to perform the work. The wait is bounded, so a wedged drive thread reports failure instead of blocking the caller indefinitely.

Diagnostics for this class of failure were improved:

  • A timeout now records the elapsed time, the port, the transport type and the command that stalled, instead of a bare message with no context.
  • A command that completes but takes unusually long is reported as a warning, so a degrading transport is visible before it fails outright.
  • The timeout, the recovery attempt and the retry outcome are summarised on a single line.

API Changes

  • Added TACDEV_COMMAND_TIMEOUT = 7 to the public C API.
  • Added TACDEV_COMMAND_TIMEOUT = 7 and its error text to the Python API.
  • Added an internal timeout exception code used to carry the condition to the API layer.
  • No existing result codes were renumbered.
  • No exported function signatures were changed.

Compatibility

Binary and source compatibility are preserved. The new value is additive, existing codes keep their values, and no exported signature changed. Existing binaries do not need to be rebuilt to keep working.

What applications should expect now

  • Commands that complete successfully continue to return 0.
  • Commands that time out now return 7 (TACDEV_COMMAND_TIMEOUT) instead of 0.
  • GetLastTACError() returns a human-readable reason for the failure.
  • Python callers receive a RuntimeError for timed-out commands, consistent with other failures.

A command that previously appeared to succeed while doing nothing may now take a few seconds longer before returning, because a recovery attempt is made first. Applications that already check result codes need no changes. Applications that ignored result codes may begin to see failures reported for operations that were silently failing before.

Port open failures

Device open behavior is not changed by this PR:

  • OpenHandleByDescription() already reported failure by returning a bad handle (0) and setting an error message, and it still behaves that way.
  • The returned error text still distinguishes causes such as a port held by another process versus a port that does not exist.
  • No new result code was introduced for open failures.

What changes is the behavior after a failed or unusable open. Commands issued in that state previously returned success; they now return 7 with an error message. Checking the result of the open call remains the recommended first step, because it reports the failure immediately rather than after a command timeout.

Validation

  • Builds clean for x64 Debug and Release.
  • Exported symbol set was compared before and after: no symbol was removed or re-signed, so existing binaries continue to link and load.
  • Exercised against a PIC32CX debug board. Normal operation showed no regression across a 72-minute session with 61 commands and several boot-mode sequences: no spurious timeouts and no unnecessary recovery attempts.
  • Verified recovering a board that had stopped acknowledging. The transport was reinitialized, the board completed its identification handshake, the retried command succeeded, and the subsequent boot-mode sequence ran normally.
  • Verified that an invalid handle is still rejected cleanly and that no exception escapes the C API boundary.

Known limitations

  • Recovery has been verified against one reproduced failure. An earlier revision of this change that reopened the port without completing the identification handshake did not recover, which is why the handshake is now required before reporting success.
  • Recovery takes a few seconds. An application with a short external timeout may still exceed it even though recovery eventually succeeds.
  • Recovery addresses the host side only. It does not prevent the underlying cause of a device dropping off the bus; unstable power or an unpowered USB hub remains an environmental issue to resolve separately.

Builds on the command-timeout reporting by attempting recovery rather than
only reporting the failure.

Background: when the debug board stops acknowledging, waitForCompletion()
times out on every subsequent command. Logs from a failing bench show that
reopening the TACDev handle does not clear this - the handle opens fine
because the port still exists, while the transport underneath stays stuck.
In that incident the condition persisted for over two hours and was only
cleared when the board physically re-enumerated on USB.

Changes:
- Add TACDriveThread::resetTransport(), a virtual defaulting to false so
  transports that cannot be reset keep their existing behaviour.
- Implement it for TACPIC32CXDriveThread: clear buffers, close, delete and
  reopen the QSerialPort. The replacement port is a new object, so the
  readyRead/errorOccurred connections that run() establishes are re-wired,
  otherwise readyRead would never fire again and every read would time out.
- Implement it for TACLiteDriveThread: close and reopen the FTDI chipset to
  force fresh FT_OpenEx handles. openFTDIDevice() only opens when isOpen()
  is false, so the close must happen first or the reopen is a no-op.
- setPinState() and quickCommand() now reset the transport and retry once
  before throwing TAC_COMMAND_TIMEOUT. quickCommand() covers bootToEDL and
  the other button commands.
- SetExternalPowerControl: add the missing try/catch. externalPowerControl()
  can throw, and this export had no handler, so a TACException could escape
  across the C boundary.

Note on naming: the string 'Wait for completion timed out' is emitted by the
generic TACDriveThread::waitForCompletion() and is not FTDI-specific, despite
how it is referenced downstream.

Verified: x64 Debug and Release build clean. Read-only API test against an
attached Alpaca Lite board passes 16/16 - load, enumerate, open, property
reads, close, and bad-handle rejection with no exception escaping an export.

Not verified: that reopening the transport clears the specific wedge seen in
production. That state cannot be induced from the host, so it needs a bench
where the fault recurs. The new log lines (resetTransport succeeded/failed,
retry after reset) report the outcome directly.
Fixes a data race and use-after-free introduced by the previous commit.

resetTransport() ran on the thread issuing the command and tore down the
transport directly - closing and deleting the QSerialPort, or closing the FTDI
chipset. But those objects belong to run() on the drive thread, which reads
and writes them continuously:

  chunk = _serialPort->readAll();
  _serialPort->write(framePackage->_codedRequest);
  _serialPort->waitForReadyRead(10);
  _ftdiChipset->write(pin, state);

Deleting _serialPort from another thread while run() dereferences it is a use
after free, and QSerialPort must only be used from its owning thread. This
could hang or crash rather than recover.

Now resetTransport() only posts a request and waits on a condition variable;
the drive thread services it in processPendingTransportReset() and does the
work in performTransportReset(). The reset is serviced at the top of the run()
loop, before the next frame is picked up, so the transport is never torn down
mid-operation.

Details:
- resetTransport() returns false immediately if the drive thread is not
  running, rather than waiting for a reset nobody will service.
- The wait is bounded at 15s. If the drive thread is itself wedged the caller
  reports failure and surfaces the original timeout instead of hanging.
- On timeout the request is withdrawn, so a later reset is not serviced by a
  stale flag after the caller has given up.
- performTransportReset() disconnects the port signals before teardown, so a
  queued readyRead cannot be delivered to a destroyed object.
- run() wakes a blocked caller on exit, and tolerates a null _serialPort in
  the idle path, since a failed reopen leaves it null.

Verified: x64 Debug and Release build clean. Read-only API test passes for
init, bad-handle rejection and exception safety. Device enumeration was not
re-tested as the board was disconnected at the time; count=0 was correct for
that state.

Not verified: recovery behaviour under a real wedge, which needs a bench where
the fault recurs.
This fault is intermittent, slow to reproduce and only observable through
logs, but the logs did not carry enough to diagnose it. Two investigations so
far were spent reconstructing information the code could simply have recorded.

What was missing:

- 'Wait for completion timed out.' was the entire message. No command, pin,
  port or elapsed time. On 10/2 there were 177 of these and the command had to
  be inferred from the following line each time.
- A command that took 11 minutes but did eventually complete was only visible
  as 'elapsed: 666140 (ms)' inside a frame dump, so it read as normal.
- The timeout, reset and retry were three separate entries that had to be
  correlated by hand.

Changes:

- waitForCompletion() now reports elapsed time, port, drive train and the
  command that stalled. The leading text stays exactly 'Wait for completion
  timed out' because TacService matches that substring to trigger a
  reinitialize; context is appended, not substituted.
- Added a 'Slow command completion' warning above 1s, so a degrading transport
  is visible before it fails outright.
- Added setLastCommandDescription(), set by setPinState(),
  sendCommandSequence() and externalPowerControl() on both transports, so a
  timeout can name the operation.
- Added a single 'TIMEOUT RECOVERY' line reporting command, reset outcome,
  retry outcome and port together.

Noise is not a concern at this volume: the 10/5 session was 2965 lines over
72 minutes, and these lines only appear on a timeout or a slow command.

Verified: x64 Debug and Release build clean. Confirmed the emitted literal
still begins with the exact string TacService matches on.
The first version of this reset reopened the port and immediately reported
success. Bench logs show why that was not enough: five cycles between 11:43
and 11:56, every one reopening in 30-90 ms and then failing the retry.

  11:43:02.991  Wait for completion timed out.
  11:43:03.006  performTransportReset: resetting serial transport
  11:43:03.057  performTransportReset: succeeded     <- 51 ms
  11:43:08.724  retry after reset failed

Comparing the two open paths explains it. Normal startup opens the port, then
run() services the queued clearBuffer and a platformID request, and the board
answers about 530 ms later:

  19:57:07.946  Com port COM9
  19:57:08.477  Request: echo 1            <- handshake
                ... *IDN?, board identifies itself

The reset path did none of that. openSerialDevice() queues clearBuffer, but
performTransportReset() is called from inside the run() loop, so nothing
drained it before the caller's retry went on the wire. The port was open and
the conversation had never been established.

Changes:
- Discard protocol state on teardown. A partially assembled frame, a pending
  frame awaiting a response, or queued commands from the timed-out operation
  would otherwise frame the reopened connection against a stale conversation,
  which is indistinguishable from an unresponsive board.
- Settle for 500 ms before reopening, rather than reopening in ~50 ms.
- After reopening, issue platformID() and drain the handshake in
  drainHandshake(), mirroring what run() does at startup. Bounded at 5s, well
  inside the caller's 15s reset timeout.
- Return success only when the board has actually identified itself. Reporting
  success on a reopened-but-silent port is what made the earlier attempt look
  like the reset had worked when the retry could never succeed.

Recovery is already re-attempted on each subsequent failing command: there is
no suppression flag, so a later command that times out runs the whole sequence
again. The bench log confirms this - five independent attempts across 13
minutes.

Verified: x64 Debug and Release build clean.

Not verified: whether a full reinitialization actually recovers the board. If
the retry still fails with the handshake reported as 'no response', the fault
is below the host transport and the next step is the firmware/USB path rather
than more software recovery.
@hangzqcom hangzqcom changed the title Report command completion timeouts Report command completion timeouts and recover the transport Oct 6, 2026
Resolves conflicts in STM32Device.h/.cpp.

develop commit 5d29d99 ('Fix battery pin toggle failure from QTAC UI') removed
STM32Device::setPinState() entirely. This branch had changed that same override
to return bool so a timeout could propagate.

Took develop's deletion. The override only applied pin inversion before
delegating to _AlpacaDevice::setPinState(), and inversion is handled in
_STM32PlatformConfiguration::getPinInvertedState(), so removing it loses
nothing. With the override gone, STM32 callers reach _AlpacaDevice::setPinState()
directly and pick up the timeout propagation from this branch without needing a
signature change here.

Verified: x64 Debug and Release build clean after the merge.
powerOff and bootToEDL could return NO_TAC_ERROR in about a millisecond while
the board never moved. Bench evidence, 2026-10-08 03:21:

  QUTS:    Entering sendCommand  03:21:29.827
           Exiting  sendCommand  03:21:29.828      <- 1 ms
  Alpaca:  ====== powerOff start ======            <- queued, never completed
           (no powerOff finish, no on_pinStateChanged)

Cause: waitForCompletion() loops only while _waitForCompletion is set. If the
flag is already clear on entry the loop is never entered and it returns true,
so quickCommand() reports success without the board acknowledging anything.

SendCommand() arms the flag before calling in, via _setCommandState(), which
is why timeouts were detected correctly on that path - including the transport
resets observed recovering at 02:49 and 03:25. _quickCommand() did not, so
powerOn, powerOff, bootToFastboot, bootToUEFI, bootToEDL and
bootToSecondaryEDL could not detect a timeout at all.

This matters most when only the underlying COM port re-enumerates and the TAC
Device protocol handle does not. QUTS emits no protocol-removed callback in
that case, so TacService has no event to react to and the result code is the
only remaining signal - and it was reporting success.

Fix: call setWaitForCompletion() in _quickCommand() before quickCommand(),
matching the pattern _setCommandState() already uses. The SendCommand path is
untouched, so the currently working full re-enumeration case is unaffected.

Logging added so the next occurrence is self-evident rather than inferred from
timing:
- completionArmed=yes|NO when a sequence is queued, with the entry count
- an explicit warning when the flag is not armed and the wait cannot verify
- completion confirmed|timed out after the wait
- the failing result and message in _quickCommand's exception handler

Verified: x64 Debug and Release build clean.

Not verified: whether the transport reset recovers a COM-port-only
re-enumeration. The two observed recoveries followed idle stalls, not a
confirmed port cycle. The new logging will show this on the next occurrence.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant