diff --git a/changelog.json b/changelog.json index a5a20f4..d83d80f 100644 --- a/changelog.json +++ b/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." ] diff --git a/internal/steppir/readframe_test.go b/internal/steppir/readframe_test.go new file mode 100644 index 0000000..4cb7d64 --- /dev/null +++ b/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{} diff --git a/internal/steppir/steppir.go b/internal/steppir/steppir.go index 64615d3..1e7d5d0 100644 --- a/internal/steppir/steppir.go +++ b/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()