chore: release v0.21.3

internal/tunergenius/linklog_test.go

@@ -0,0 +1,100 @@
+package tunergenius
+
+import (
+	"bufio"
+	"net"
+	"os"
+	"strings"
+	"testing"
+	"time"
+)
+
+// captureLog redirects the stream applog.Printf always writes to, and returns a
+// stop function yielding what was logged. Reading only after stop keeps the
+// collector goroutine and the test off the same slice.
+func captureLog() func() []string {
+	orig := os.Stderr
+	r, w, _ := os.Pipe()
+	os.Stderr = w
+	var lines []string
+	done := make(chan struct{})
+	go func() {
+		sc := bufio.NewScanner(r)
+		for sc.Scan() {
+			lines = append(lines, sc.Text())
+		}
+		close(done)
+	}()
+	return func() []string {
+		os.Stderr = orig
+		w.Close()
+		<-done
+		r.Close()
+		return lines
+	}
+}
+
+// A tuner that answers, then vanishes mid-session. A drop used to leave no trace
+// at all, so "did the tuner disconnect, or is the meter just reading a gap
+// between syllables?" was unanswerable from the log. It must now log — and log
+// ONCE, not on every 400 ms retry.
+func TestLinkDownLoggedOnceNotPerRetry(t *testing.T) {
+	ln, err := net.Listen("tcp", "127.0.0.1:0")
+	if err != nil {
+		t.Fatal(err)
+	}
+	port := ln.Addr().(*net.TCPAddr).Port
+
+	die := make(chan struct{})
+	go func() {
+		conn, err := ln.Accept()
+		if err != nil {
+			return
+		}
+		conn.Write([]byte("V1.2.11\n"))
+		buf := make([]byte, 256)
+		for {
+			n, err := conn.Read(buf)
+			if err != nil {
+				return
+			}
+			id := strings.TrimPrefix(strings.SplitN(string(buf[:n]), "|", 2)[0], "C")
+			conn.Write([]byte("R" + id + "|0|status state=1 fwd=60.7 swr=-25 active=1\n"))
+			select {
+			case <-die:
+				conn.Close()
+				ln.Close()
+				return
+			default:
+			}
+		}
+	}()
+
+	stop := captureLog()
+	c := New("127.0.0.1", port, "")
+	if err := c.Start(); err != nil {
+		stop()
+		t.Fatal(err)
+	}
+
+	time.Sleep(1200 * time.Millisecond)
+	connected := c.GetStatus().Connected
+	close(die)
+	time.Sleep(2 * time.Second) // ~5 poll cycles with the tuner gone
+	c.Stop()
+	lines := stop()
+
+	if !connected {
+		t.Fatal("the client never reached the fake tuner — the rest of the test is meaningless")
+	}
+	down := 0
+	for _, l := range lines {
+		if strings.Contains(l, "link DOWN") {
+			down++
+		}
+	}
+	t.Logf("logged:\n%s", strings.Join(lines, "\n"))
+	if down != 1 {
+		t.Errorf("got %d 'link DOWN' lines, want exactly 1 — the poll retries many times in a 3 s outage and must not repeat itself", down)
+	}
+}

internal/tunergenius/tunergenius.go

@@ -34,8 +34,7 @@ const (
 	// Poll fast so the meters track TX like the amplifier does (the amp's numbers
 	// ride the real-time Flex UDP stream; the tuner is a synchronous TCP poll, so
 	// a slow interval made its SWR/power lag noticeably behind).
-	pollEvery      = 400 * time.Millisecond
-	reconnectDelay = 2 * time.Second
+	pollEvery = 400 * time.Millisecond
 )
 
 // Channel is the live state of one of the tuner's two RF channels (A / B). The
@@ -215,6 +214,17 @@ func (c *Client) Activate(ch int) error {
 func (c *Client) pollLoop() {
 	t := time.NewTicker(pollEvery)
 	defer t.Stop()
+	// Outage bookkeeping. A dropped link used to be entirely silent: the poll just
+	// set Connected=false and retried, so "did the tuner disconnect, or is the
+	// meter simply reading a gap between syllables?" could not be answered from
+	// the log. Now an outage logs once when it starts and once when it ends, with
+	// how long it lasted.
+	//
+	// Once, not every retry: the poll comes round every 400 ms, and a tuner that
+	// is switched off would otherwise bury the log. These are local to the one
+	// goroutine that polls — ensureConnected has no other caller — so they need no
+	// locking.
+	var downSince time.Time
 	for {
 		select {
 		case <-c.stop:
@@ -223,16 +233,28 @@ func (c *Client) pollLoop() {
 			fresh := false
 			if c.needConnect() {
 				if err := c.ensureConnected(); err != nil {
+					if downSince.IsZero() {
+						downSince = time.Now()
+						applog.Printf("tunergenius: link DOWN — cannot reach %s:%d: %v (retrying)", c.host, c.port, err)
+					}
 					c.setStatus(func(s *Status) { s.Connected = false; s.LastError = "dial: " + err.Error() })
 					continue
 				}
 				fresh = true
+				if !downSince.IsZero() {
+					applog.Printf("tunergenius: link RESTORED after %s down", time.Since(downSince).Round(time.Second))
+					downSince = time.Time{}
+				}
 			}
 			// One-shot on a fresh link: learn the hardware variant (3-way vs SO2R).
 			if fresh {
 				_, _ = c.command("info")
 			}
 			if _, err := c.command("status"); err != nil {
+				if downSince.IsZero() {
+					downSince = time.Now()
+					applog.Printf("tunergenius: link DOWN — poll failed: %v", err)
+				}
 				c.dropConn()
 				c.setStatus(func(s *Status) { s.Connected = false; s.LastError = err.Error() })
 			}