fix(steppir): a silent controller wedged the driver for good

io.ReadFull cannot be used on a serial port, and it was.

On Windows a serial read that times out returns (0, nil) — on this transport a
timeout is not an error. io.ReadFull loops while err == nil, so a controller
that goes quiet for one poll, or answers with a truncated frame, spins it
forever. It holds ioMu throughout, and that is the whole failure the operator
sees:

  - the poll goroutine never returns, so nothing is ever logged about a fault
    and the cached status keeps the antenna looking connected;
  - every command blocks on the same mutex, and the trace line sat AFTER the
    lock, so even the attempt left no trace.

One dropped reply on a 4800-baud link therefore stopped the antenna responding
until OpsLog was restarted, with a log that showed the antenna starting, a few
status frames, and then nothing — which is exactly how it was reported.

Reads are now bounded: three seconds for an 11-byte frame that takes 23 ms on
the wire. Giving up returns an error, and the poll loop already knows what to do
with one — say so and reconnect. The command trace moved ahead of the lock, so
what the operator asked for is in the log even when the answer is not.

The SPE driver reads through a bufio.Reader, whose ErrNoProgress guard already
covers this; the ADIF parser reads a file. This was the only exposed one.

changelog.json

@@ -8,6 +8,7 @@
       "DX cluster: the log times the connection and the first spot, so a slow first launch can be told apart from a quiet node.",
       "Generic HTTP relay: its URLs were never actually sent — fixed. {value} sends the relay's label, {relay-1} counts from zero, no host needed.",
       "Switching profile now reconnects the amplifier, antenna, Antenna Genius and tuner — they stayed on the previous profile's ports until you saved Settings.",
+      "SteppIR: one missed reply used to wedge the link — the antenna stopped responding, with nothing at all in the log. It now recovers on its own.",
       "The log now says when a motorized antenna is connected but tracking is off, instead of a line that read like a fault.",
       "DXHunter spot clicks tune the rig again: the frequency it sends is read in whatever unit it uses, not always as MHz."
     ],
@@ -17,6 +18,7 @@
       "Cluster DX : le journal chronomètre la connexion et le premier spot, pour distinguer un premier lancement lent d’un nœud silencieux.",
       "Relais HTTP générique : ses URL n’étaient jamais envoyées — corrigé. {value} envoie le libellé du relais, {relay-1} compte de zéro, hôte inutile.",
       "Changer de profil reconnecte l’ampli, l’antenne, l’Antenna Genius et le tuner — ils restaient sur les ports du profil précédent jusqu’à un Enregistrer.",
+      "SteppIR : une seule réponse manquée bloquait la liaison — l’antenne ne répondait plus, sans rien dans le journal. Elle se rétablit maintenant seule.",
       "Le journal indique désormais qu’une antenne motorisée est connectée mais que le suivi est désactivé, au lieu d’une ligne qui ressemblait à une panne.",
       "Les clics de spot DXHunter accordent à nouveau le rig : la fréquence envoyée est lue dans son unité réelle, plus toujours en MHz."
     ]

internal/steppir/readframe_test.go

@@ -0,0 +1,113 @@
+package steppir
+
+import (
+	"errors"
+	"io"
+	"testing"
+	"time"
+)
+
+// silentPort is a serial port that has stopped answering: every read times out.
+// On Windows that is reported as (0, nil) — a timeout is not an error on this
+// transport — which is precisely what io.ReadFull cannot survive.
+type silentPort struct{ reads int }
+
+func (p *silentPort) Read(b []byte) (int, error) {
+	p.reads++
+	time.Sleep(5 * time.Millisecond) // stand in for the port's read timeout
+	return 0, nil
+}
+func (p *silentPort) Write(b []byte) (int, error) { return len(b), nil }
+func (p *silentPort) Close() error                { return nil }
+
+// A controller that goes quiet must make the read FAIL, not hang. Hanging held
+// the io mutex, so the poll loop never reported a fault and every operator
+// command blocked behind it: the antenna stopped responding and the log had
+// nothing in it.
+func TestReadFrameGivesUpOnASilentController(t *testing.T) {
+	done := make(chan error, 1)
+	go func() {
+		done <- readFrame(&silentPort{}, make([]byte, 11), 100*time.Millisecond)
+	}()
+	select {
+	case err := <-done:
+		if err == nil {
+			t.Fatal("a silent controller was reported as a good frame")
+		}
+	case <-time.After(3 * time.Second):
+		t.Fatal("readFrame never returned — the driver is wedged exactly as it was in the field")
+	}
+}
+
+// dribblePort delivers the frame a few bytes at a time, with empty reads in
+// between — a slow 4800-baud link, which must still assemble one frame.
+type dribblePort struct {
+	data []byte
+	step int
+	idle int // empty reads before each chunk
+	n    int
+}
+
+func (p *dribblePort) Read(b []byte) (int, error) {
+	if p.n < p.idle {
+		p.n++
+		return 0, nil
+	}
+	p.n = 0
+	if len(p.data) == 0 {
+		return 0, nil
+	}
+	k := p.step
+	if k > len(p.data) {
+		k = len(p.data)
+	}
+	if k > len(b) {
+		k = len(b)
+	}
+	copy(b, p.data[:k])
+	p.data = p.data[k:]
+	return k, nil
+}
+func (p *dribblePort) Write(b []byte) (int, error) { return len(b), nil }
+func (p *dribblePort) Close() error                { return nil }
+
+func TestReadFrameAssemblesASlowFrame(t *testing.T) {
+	want := []byte{'@', 'A', 0x00, 0x20, 0x1E, 0xA8, 0x00, 0x05, 0x30, 0x37, 0x0D}
+	p := &dribblePort{data: append([]byte(nil), want...), step: 3, idle: 2}
+	buf := make([]byte, 11)
+	if err := readFrame(p, buf, time.Second); err != nil {
+		t.Fatalf("readFrame: %v", err)
+	}
+	for i := range want {
+		if buf[i] != want[i] {
+			t.Fatalf("read % X, want % X", buf, want)
+		}
+	}
+}
+
+// A truncated frame is a failure, not a frame. The controller sending 5 bytes
+// and stopping used to spin forever on the missing 6.
+func TestReadFrameRejectsATruncatedFrame(t *testing.T) {
+	p := &dribblePort{data: []byte{'@', 'A', 0x00, 0x20, 0x1E}, step: 5}
+	err := readFrame(p, make([]byte, 11), 100*time.Millisecond)
+	if err == nil {
+		t.Fatal("a 5-byte frame was accepted as 11")
+	}
+}
+
+// A real error still comes straight back.
+func TestReadFrameReturnsPortErrors(t *testing.T) {
+	want := errors.New("port closed")
+	p := errPort{err: want}
+	if err := readFrame(p, make([]byte, 11), time.Second); !errors.Is(err, want) {
+		t.Fatalf("err = %v, want %v", err, want)
+	}
+}
+
+type errPort struct{ err error }
+
+func (p errPort) Read([]byte) (int, error)    { return 0, p.err }
+func (p errPort) Write(b []byte) (int, error) { return len(b), nil }
+func (p errPort) Close() error                { return nil }
+
+var _ io.ReadWriteCloser = errPort{}

internal/steppir/steppir.go

@@ -419,6 +419,45 @@ func drain(conn io.ReadWriteCloser) int {
 	return total
 }
 
+// frameTimeout bounds the wait for one 11-byte status reply. At 4800 baud the
+// frame itself takes ~23 ms; three seconds is a controller that is not going to
+// answer this query.
+const frameTimeout = 3 * time.Second
+
+// readFrame reads exactly len(buf) bytes, or gives up.
+//
+// io.ReadFull CANNOT be used on a serial port, and using it here is what made an
+// antenna "stop responding after a while" with nothing whatsoever in the log.
+//
+// On Windows a serial read that times out returns (0, nil) — a timeout is not an
+// error on this transport. io.ReadFull loops while err == nil, so a controller
+// that goes quiet, or sends a truncated frame, spins it forever. It holds ioMu
+// the whole time, and that is the part the operator sees: the poll goroutine
+// never returns to report a fault, so the last status stays on screen and the
+// link still looks connected — while every command blocks on the same mutex.
+// The trace line used to sit AFTER that lock, so even the attempt went unlogged.
+// One dropped reply on a 4800-baud link wedged the driver until OpsLog restarted.
+//
+// Giving up returns an error, which the poll loop already knows how to handle:
+// it says so in the log and reconnects.
+func readFrame(conn io.ReadWriteCloser, buf []byte, d time.Duration) error {
+	deadline := time.Now().Add(d)
+	for n := 0; n < len(buf); {
+		m, err := conn.Read(buf[n:])
+		if err != nil {
+			return err
+		}
+		n += m
+		if n >= len(buf) {
+			return nil
+		}
+		if time.Now().After(deadline) {
+			return fmt.Errorf("timed out after %s with %d of %d bytes", d, n, len(buf))
+		}
+	}
+	return nil
+}
+
 func (c *Client) queryStatus() (*Status, error) {
 	c.connMu.Lock()
 	conn := c.conn
@@ -438,7 +477,7 @@ func (c *Client) queryStatus() (*Status, error) {
 		return nil, fmt.Errorf("write status cmd: %w", err)
 	}
 	buf := make([]byte, 11)
-	if _, err := io.ReadFull(conn, buf); err != nil {
+	if err := readFrame(conn, buf, frameTimeout); err != nil {
 		return nil, fmt.Errorf("read status: %w", err)
 	}
 	// Reject anything that isn't a framed reply rather than decoding garbage into
@@ -523,9 +562,14 @@ func (c *Client) writeCmd(pkt []byte) error {
 	if conn == nil {
 		return fmt.Errorf("steppir: not connected")
 	}
+	// Traced BEFORE taking the lock, not after. A command waits here for the poll
+	// in flight, and when that wait was unbounded the log showed no sign the
+	// operator had asked for anything at all — the one fact that would have named
+	// the fault. The line now means "asked for"; a failure to write is reported
+	// by the caller.
+	log.Printf("steppir: → % X", pkt)
 	c.ioMu.Lock()
 	defer c.ioMu.Unlock()
-	log.Printf("steppir: → % X", pkt)
 	setDeadline(conn, 3*time.Second)
 	if _, err := conn.Write(pkt); err != nil {
 		c.closeConn()