OpsLog/internal/steppir/steppir.go

// Package steppir controls a SteppIR SDA-100 / SDA-2000 antenna controller over
// its "Transceiver Interface" serial protocol, reached either directly on a COM
// port or over TCP through an RS232↔Ethernet bridge (the same way OpsLog talks to
// an Ultrabeam). The client mirrors the ultrabeam.Client surface so the app can
// drive either behind one interface.
//
// Protocol (cross-checked against the SteppIR "Transceiver Interface Operation"
// note, the we7u/steppir library, and the la1k.no write-up — three independent
// sources that agree, which is what makes the byte layout trustworthy):
//
//	SET   : "@A" <freq> 00 <dir> <cmd> 00 0x0D          (11 bytes)
//	        <freq> = int32 big-endian of (Hz / 10)
//	        <dir>  = 0x00 normal · 0x40 180° · 0x80 bidirectional · 0x20 3/4-wave
//	        <cmd>  = '1' set freq+dir · 'R' autotrack ON · 'U' autotrack OFF
//	                 'S' home/retract · 'V' calibrate
//	STATUS: "?A" 0x0D  → 11 bytes back:
//	        [2:6] int32 big-endian frequency (× 10 = Hz)
//	        [6]   active-motor bitmask (0xFF = command received / setup)
//	        [7] & 0xE0 direction
//
// Timing: the controller needs ≥100 ms between commands and dislikes status
// polls faster than ~10/s. The poll loop runs at 2 s, well inside that.
package steppir

import (
	"bytes"
	"encoding/binary"
	"errors"
	"fmt"
	"io"
	"log"
	"net"
	"strings"
	"sync"
	"time"

	"go.bug.st/serial"
)

// errBadFrame marks a reply that isn't a well-formed status frame. It means
// "ignore this poll", not "the link is down".
var errBadFrame = errors.New("steppir: malformed status frame")

// Direction values, matching the app-wide convention (also used by Ultrabeam):
// 0 normal, 1 reverse (180°), 2 bidirectional.
const (
	DirNormal = 0
	Dir180    = 1
	DirBi     = 2
)

// SteppIR direction bytes on the wire.
const (
	wireNormal = 0x00
	wire180    = 0x40
	wireBi     = 0x80
)

// pendingDirTTL is how long a commanded direction is trusted over the
// controller's own report. The elements physically re-tune to swap director and
// reflector, and the SDA only reports the new pattern once it starts that move,
// so a few seconds is not enough — 4 s (the original value) had the UI snapping
// back to "normal" while the antenna was on its way to 180°. Long enough to
// cover a real move, short enough that a command the controller never received
// self-corrects instead of lying forever.
const pendingDirTTL = 45 * time.Second

// Transport says how to reach the controller.
type Transport struct {
	Mode string // "tcp" | "serial"
	Host string // tcp
	Port int    // tcp
	COM  string // serial device (COM3, /dev/ttyUSB0)
	Baud int    // serial baud (controller default 9600; 1200-19200 valid)
}

// Status is the antenna state, in the same shape the app reads from the
// Ultrabeam so the two are interchangeable at the UI.
type Status struct {
	Connected    bool `json:"connected"`
	Frequency    int  `json:"frequency"` // kHz
	Band         int  `json:"band"`      // 0 (SteppIR does not report a band index)
	Direction    int  `json:"direction"` // 0 normal, 1 180°, 2 bidirectional
	MotorsMoving int  `json:"motors_moving"`
}

type Client struct {
	tr Transport

	connMu sync.Mutex
	conn   io.ReadWriteCloser
	// openFails counts consecutive failures to reopen the port, so the retry
	// reports the first one and the recovery, and stays quiet in between.
	// Guarded by connMu.
	openFails int

	// ioMu serialises EVERY exchange on the shared connection — a status query
	// (write "?A" then read 11 bytes) and a command write must never interleave,
	// or their bytes mix on the wire and both frames are corrupted. The status
	// poll runs on one goroutine, tuning on another, so this is essential.
	ioMu sync.Mutex

	statusMu   sync.RWMutex
	lastStatus *Status
	lastSetKHz int
	// lastDriftKHz is the frequency last reported for a controller that had gone
	// somewhere other than where it was told, so the disagreement is stated once
	// and not on every poll. Zero when it is where it should be.
	lastDriftKHz int

	// lastRaw holds the previous raw status frame so we only log a status line
	// when the controller's reply actually changes — enough to diagnose a stuck
	// "motors moving" read (which drives the app's TX-inhibit interlock) without
	// spamming the log every 2 s poll.
	lastRaw []byte

	// A just-commanded direction is held until the controller's poll reports it —
	// the motors take a second or two, and a stale poll would otherwise snap the
	// UI back. Same trick as the Ultrabeam client.
	//
	// The hold is deliberately long (pendingDirTTL). It is not just a UI nicety:
	// the follow loop re-tunes with the direction it reads back from this status,
	// so a single stale poll reading "normal" would make OpsLog command the
	// antenna out of 180° all by itself.
	pendingDir    int
	pendingDirAt  time.Time
	pendingDirSet bool

	stopChan chan struct{}
	// done is closed by the poll loop on its way out, so Stop can wait for the
	// serial port to be genuinely released — see Stop.
	done    chan struct{}
	running bool
}

func New(tr Transport) *Client {
	if tr.Baud <= 0 {
		tr.Baud = 9600
	}
	return &Client{tr: tr, stopChan: make(chan struct{})}
}

func (c *Client) Start() error {
	c.running = true
	c.done = make(chan struct{})
	go c.pollLoop()
	return nil
}

// Stop closes the link and WAITS for the poll loop to leave.
//
// Closing the port from another goroutine does not undo an open() the loop is
// already inside: that open returns a fresh handle which the loop then stores,
// and the stopped client goes on owning the serial port. The next client — a
// settings save, a profile switch — cannot open it, and the operator sees
// "Serial port busy" with no other program running.
//
// Bounded, so a device stuck in the driver cannot freeze a settings save.
func (c *Client) Stop() {
	if !c.running {
		return
	}
	c.running = false
	close(c.stopChan)
	c.connMu.Lock()
	if c.conn != nil {
		c.conn.Close()
		c.conn = nil
	}
	c.connMu.Unlock()
	if c.done == nil {
		return
	}
	select {
	case <-c.done:
	case <-time.After(6 * time.Second):
		log.Printf("steppir: poll loop did not exit within 6s — %s may stay busy a moment longer", c.target())
	}
}

// LastSetKHz returns the frequency last commanded, or 0.
func (c *Client) LastSetKHz() int {
	c.statusMu.RLock()
	defer c.statusMu.RUnlock()
	return c.lastSetKHz
}

func (c *Client) GetStatus() (*Status, error) {
	c.statusMu.RLock()
	defer c.statusMu.RUnlock()
	if c.lastStatus == nil {
		return &Status{Connected: false}, nil
	}
	return c.lastStatus, nil
}

// open dials the transport. Callers hold connMu.
func (c *Client) open() (io.ReadWriteCloser, error) {
	switch c.tr.Mode {
	case "serial":
		if c.tr.COM == "" {
			return nil, fmt.Errorf("steppir: no serial port configured")
		}
		// 8N1 spelled out rather than left to the library defaults: a controller
		// that answers nothing must not have a line format that depends on them.
		p, err := serial.Open(c.tr.COM, &serial.Mode{
			BaudRate: c.tr.Baud,
			DataBits: 8,
			Parity:   serial.NoParity,
			StopBits: serial.OneStopBit,
		})
		if err != nil {
			return nil, err
		}
		// A finite read timeout so a silent controller doesn't wedge the poll loop.
		_ = p.SetReadTimeout(2 * time.Second)
		return p, nil
	default: // tcp
		if c.tr.Host == "" {
			return nil, fmt.Errorf("steppir: no host configured")
		}
		d := net.Dialer{Timeout: 5 * time.Second}
		return d.Dial("tcp", net.JoinHostPort(c.tr.Host, fmt.Sprintf("%d", c.tr.Port)))
	}
}

// openFailQuiet is how many consecutive failed reopens are reported before the
// loop goes quiet about them. A port that has gone (adapter unplugged, another
// program holding it) stays gone, and one line every two seconds would be the
// entire log.
const openFailQuiet = 3

// noteOpenFailure logs a failure to reopen the port, throttled. Caller must NOT
// hold connMu — it is taken here.
func (c *Client) noteOpenFailure(err error) {
	c.connMu.Lock()
	c.openFails++
	n := c.openFails
	c.connMu.Unlock()
	switch {
	case n <= openFailQuiet:
		log.Printf("steppir: cannot open %s: %v%s (attempt %d)", c.target(), err, portBusyHint(c.tr.Mode, c.tr.COM, err), n)
	case n == openFailQuiet+1:
		log.Printf("steppir: still cannot open %s — retrying every 2 s, further attempts will not be logged until it comes back", c.target())
	}
}

// target names what the client is trying to reach, for the log.
func (c *Client) target() string {
	if c.tr.Mode == "serial" {
		return fmt.Sprintf("%s @ %d baud", c.tr.COM, c.tr.Baud)
	}
	return fmt.Sprintf("%s:%d", c.tr.Host, c.tr.Port)
}

func (c *Client) pollLoop() {
	// Signals Stop that the port is genuinely released.
	defer func() {
		c.connMu.Lock()
		if c.conn != nil {
			c.conn.Close()
			c.conn = nil
		}
		c.connMu.Unlock()
		if c.done != nil {
			close(c.done)
		}
	}()
	ticker := time.NewTicker(2 * time.Second)
	defer ticker.Stop()
	for {
		select {
		case <-c.stopChan:
			return
		case <-ticker.C:
			c.connMu.Lock()
			if c.conn == nil {
				conn, err := c.open()
				if err != nil {
					c.connMu.Unlock()
					c.setDisconnected()
					// SAY SO. This retried every two seconds in complete silence,
					// so an antenna that lost its port stopped answering and the
					// log had nothing at all after the disconnection — which is
					// exactly what an operator reports as "it worked for a while
					// and then it didn't". Throttled, because a port that is gone
					// stays gone and this would otherwise be the whole log.
					c.noteOpenFailure(err)
					continue
				}
				if c.openFails > 0 {
					log.Printf("steppir: reconnected after %d failed attempt(s)", c.openFails)
					c.openFails = 0
				}
				c.conn = conn
			}
			c.connMu.Unlock()

			st, err := c.queryStatus()
			if errors.Is(err, errBadFrame) {
				// Framing glitch, not a dead link: skip this tick and keep the
				// previous status. Dropping the connection here would blink the
				// UI to "disconnected" over one garbled reply.
				continue
			}
			if err != nil {
				log.Printf("steppir: status query failed, reconnecting: %v", err)
				c.closeConn()
				c.setDisconnected()
				continue
			}
			st.Connected = true
			c.statusMu.Lock()
			c.applyPendingDir(st)
			c.lastStatus = st
			c.statusMu.Unlock()
			c.checkDrift(st)
		}
	}
}

// driftToleranceKHz is how far the controller's reported frequency may sit from
// the one we commanded before it is worth saying so. A SteppIR quantises to its
// own grid, so a few kHz is normal and must not be reported as a fault.
const driftToleranceKHz = 10

// checkDrift reports a controller that settled somewhere other than where it was
// told to go.
//
// This exists because of a log that read as "the antenna stops responding": every
// tune was commanded, acknowledged on the next poll with the requested frequency,
// and then REPLACED on the poll after by a different one — 21075 asked, 21075
// confirmed, 21050 reported, over and over, with the operator tuning again each
// time. Nothing in the log named that, so it looked like a dead link rather than
// a controller with a mind of its own (its own radio interface tracking the rig,
// or a front-panel mode that overrides the host).
//
// Only when the motors have stopped: a frequency read mid-travel is not a
// disagreement, it is an antenna on its way. And only when the value changes, so
// a controller parked somewhere else does not fill the log.
func (c *Client) checkDrift(st *Status) {
	if st.MotorsMoving != 0 {
		return
	}
	c.statusMu.Lock()
	want := c.lastSetKHz
	last := c.lastDriftKHz
	if want <= 0 || st.Frequency <= 0 {
		c.statusMu.Unlock()
		return
	}
	diff := st.Frequency - want
	if diff < 0 {
		diff = -diff
	}
	if diff <= driftToleranceKHz {
		c.lastDriftKHz = 0 // back where it was asked to be
		c.statusMu.Unlock()
		return
	}
	if last == st.Frequency {
		c.statusMu.Unlock()
		return // already said, and it has not moved since
	}
	c.lastDriftKHz = st.Frequency
	c.statusMu.Unlock()
	log.Printf("steppir: commanded %d kHz but the controller settled on %d kHz — "+
		"something else is driving it (its own radio interface, or a front-panel mode overriding the host)",
		want, st.Frequency)
}

// applyPendingDir replaces a freshly polled direction with the one the operator
// last commanded, until the controller confirms it (or the hold expires). The
// caller holds statusMu.
func (c *Client) applyPendingDir(st *Status) {
	if !c.pendingDirSet {
		return
	}
	switch {
	case st.Direction == c.pendingDir:
		c.pendingDirSet = false // confirmed — trust the controller's reports again
	case time.Since(c.pendingDirAt) > pendingDirTTL:
		c.pendingDirSet = false
		log.Printf("steppir: controller never confirmed direction %d (still reports %d) — dropping the hold",
			c.pendingDir, st.Direction)
	default:
		st.Direction = c.pendingDir
	}
}

func (c *Client) setDisconnected() {
	c.statusMu.Lock()
	c.lastStatus = &Status{Connected: false}
	c.statusMu.Unlock()
}

func (c *Client) closeConn() {
	c.connMu.Lock()
	if c.conn != nil {
		c.conn.Close()
		c.conn = nil
	}
	c.connMu.Unlock()
}

// setDeadline applies a read/write deadline on TCP; serial uses its own timeout.
func setDeadline(conn io.ReadWriteCloser, d time.Duration) {
	if nc, ok := conn.(net.Conn); ok {
		_ = nc.SetDeadline(time.Now().Add(d))
	}
}

// setReadTimeout bounds a single read on either transport, so a drain can tell
// "nothing more queued" from "still arriving" without blocking.
func setReadTimeout(conn io.ReadWriteCloser, d time.Duration) {
	switch t := conn.(type) {
	case net.Conn:
		_ = t.SetReadDeadline(time.Now().Add(d))
	case serial.Port:
		_ = t.SetReadTimeout(d)
	}
}

// restoreTimeouts puts the normal exchange timeouts back after a drain shortened
// them.
func restoreTimeouts(conn io.ReadWriteCloser) {
	setDeadline(conn, 3*time.Second) // TCP: read + write
	setReadTimeout(conn, 2*time.Second)
}

// drain throws away everything already sitting in the input buffer and returns
// how many bytes it discarded.
//
// This is the fix for the antenna's state appearing tens of seconds out of date.
// The SDA controller does not only answer "?A" — it also pushes status frames on
// its own (front-panel changes, autotrack moves, each command it processes). We
// consume exactly one frame per poll, so every unsolicited frame adds one to a
// backlog that only ever grows: reading 11 bytes then returns a frame from
// minutes ago. The field log showed it plainly — two consecutive polls 4 s apart
// reporting 28280 kHz then 14200 kHz, a frequency last used hours earlier, and a
// 180° command not showing up in the status for ~40 s (long after the UI had
// given up waiting and snapped the button back to "normal"). Emptying the buffer
// immediately before each query means the frame we then read is the answer to
// THIS query.
func drain(conn io.ReadWriteCloser) int {
	buf := make([]byte, 512)
	total := 0
	// Bounded so a controller that streams continuously can't hold the poll
	// goroutine here forever. 32 × 512 B is ~1500 frames — far more backlog than
	// any real link builds up, and it only costs one 30 ms timeout when the
	// buffer is already empty (reads return immediately while data is queued).
	for i := 0; i < 32; i++ {
		setReadTimeout(conn, 30*time.Millisecond)
		n, err := conn.Read(buf)
		total += n
		if err != nil || n == 0 { // timeout / nothing left
			break
		}
	}
	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
	c.connMu.Unlock()
	if conn == nil {
		return nil, fmt.Errorf("steppir: not connected")
	}
	c.ioMu.Lock()
	defer c.ioMu.Unlock()
	// Discard any frame the controller pushed on its own since the last poll, so
	// what we read below is this query's answer and not a stale backlog entry.
	if n := drain(conn); n > 0 {
		log.Printf("steppir: discarded %d stale byte(s) queued by the controller before polling", n)
	}
	restoreTimeouts(conn)
	if _, err := conn.Write([]byte("?A\r")); err != nil {
		return nil, fmt.Errorf("write status cmd: %w", err)
	}
	buf := make([]byte, 11)
	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
	// a frequency and a direction the app would then act on.
	if buf[0] != '@' || buf[1] != 'A' || buf[10] != 0x0D {
		log.Printf("steppir: ignoring malformed status frame % X", buf)
		drain(conn) // resync: drop the rest of whatever we landed mid-way through
		restoreTimeouts(conn)
		return nil, errBadFrame
	}
	st, err := parseStatus(buf)
	// Log the raw frame + decode whenever it changes. The motor byte (buf[6]) is
	// what decides st.MotorsMoving, and that in turn drives the app's "block TX
	// while moving" interlock — so if a controller (e.g. with its INHIBIT engaged)
	// reports a byte we misread as perpetual motion, this line makes it visible.
	if err == nil && !bytes.Equal(buf, c.lastRaw) {
		c.lastRaw = append(c.lastRaw[:0], buf...)
		log.Printf("steppir: status ← % X  (freq=%d kHz dir=%d moving=%d motorByte=0x%02X dirByte=0x%02X)",
			buf, st.Frequency, st.Direction, st.MotorsMoving, buf[6], buf[7])
	}
	return st, err
}

// parseStatus decodes an 11-byte status frame.
func parseStatus(b []byte) (*Status, error) {
	if len(b) < 11 {
		return nil, fmt.Errorf("steppir: short status frame (%d bytes)", len(b))
	}
	freqHz := int(int32(binary.BigEndian.Uint32(b[2:6]))) * 10
	active := b[6]
	dir := decodeDir(b[7])
	// active-motors byte: one bit per element that is currently moving.
	//   0x04 driver · 0x08 DIR1 · 0x10 reflector · 0x20 DIR2  (mask 0x3C)
	// Bit 0 (0x01) is documented as always set — not a motor. 0xFF means the
	// controller just received a command, not motion. So "moving" is precisely
	// "any real motor bit set", ignoring the always-on bit and the ack value.
	const motorBits = 0x3C
	moving := 0
	if active != 0xFF && active&motorBits != 0 {
		moving = 1
	}
	return &Status{Frequency: freqHz / 1000, Direction: dir, MotorsMoving: moving}, nil
}

func decodeDir(b byte) int {
	switch b & 0xE0 {
	case wireBi:
		return DirBi
	case wire180:
		return Dir180
	default:
		return DirNormal
	}
}

func dirWireByte(dir int) byte {
	switch dir {
	case Dir180:
		return wire180
	case DirBi:
		return wireBi
	default:
		return wireNormal
	}
}

// buildSet frames a SET command: "@A" <freq be32 of Hz/10> 00 <dir> <cmd> 00 CR.
func buildSet(freqHz int, dir int, cmd byte) []byte {
	var f [4]byte
	binary.BigEndian.PutUint32(f[:], uint32(freqHz/10))
	out := make([]byte, 0, 11)
	out = append(out, '@', 'A')
	out = append(out, f[:]...)
	out = append(out, 0x00, dirWireByte(dir), cmd, 0x00, 0x0D)
	return out
}

func (c *Client) writeCmd(pkt []byte) error {
	c.connMu.Lock()
	conn := c.conn
	c.connMu.Unlock()
	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()
	setDeadline(conn, 3*time.Second)
	if _, err := conn.Write(pkt); err != nil {
		c.closeConn()
		return err
	}
	// The controller needs breathing room between commands.
	time.Sleep(120 * time.Millisecond)
	return nil
}

// SetFrequency tunes the elements to freqKhz with the given direction.
//
// AUTOTRACK is (re-)enabled first, EVERY time: the controller ignores frequency
// sets unless it is in AUTOTRACK mode ("when not in AUTOTRACK only CALIBRATE and
// RETRACT work"), and it can be out of AUTOTRACK at power-on, after a Home, or if
// switched off on the front panel. Sending the 'R' command each tune is cheap and
// makes tuning work regardless of the controller's current mode — which is what
// was silently failing before.
func (c *Client) SetFrequency(freqKhz int, direction int) error {
	if err := c.writeCmd(buildSet(freqKhz*1000, direction, 'R')); err != nil { // AUTOTRACK ON
		return err
	}
	if err := c.writeCmd(buildSet(freqKhz*1000, direction, '1')); err != nil { // set freq + dir
		return err
	}
	c.statusMu.Lock()
	c.lastSetKHz = freqKhz
	c.pendingDir, c.pendingDirAt, c.pendingDirSet = direction, time.Now(), true
	c.statusMu.Unlock()
	return nil
}

// SetDirection changes the pattern. SteppIR has no standalone direction command —
// it is a SET with the current frequency and the new direction byte.
func (c *Client) SetDirection(direction int) error {
	khz := c.LastSetKHz()
	if khz <= 0 {
		if st, _ := c.GetStatus(); st != nil {
			khz = st.Frequency
		}
	}
	if khz <= 0 {
		return fmt.Errorf("steppir: no frequency known yet — cannot set direction")
	}
	return c.SetFrequency(khz, direction)
}

// Retract homes the elements into the hubs (storage). This drops the controller
// out of AUTOTRACK, but that is handled transparently: the next SetFrequency
// re-issues AUTOTRACK ON before tuning.
func (c *Client) Retract() error {
	// A valid frequency must accompany the command; reuse the last one.
	khz := c.LastSetKHz()
	if khz <= 0 {
		if st, _ := c.GetStatus(); st != nil && st.Frequency > 0 {
			khz = st.Frequency
		} else {
			khz = 14000 // any in-range value; the controller just homes
		}
	}
	return c.writeCmd(buildSet(khz*1000, DirNormal, 'S'))
}

// portBusyHint turns "Serial port busy" into something actionable — see the
// identical note in internal/ultrabeam.
func portBusyHint(mode, com string, err error) string {
	if mode != "serial" || err == nil {
		return ""
	}
	msg := strings.ToLower(err.Error())
	if !strings.Contains(msg, "busy") && !strings.Contains(msg, "access is denied") && !strings.Contains(msg, "denied") {
		return ""
	}
	return " — another program already has " + com + " open (the SteppIR control window, PstRotator, a terminal). A COM port has one owner: close the other program, then OpsLog can connect."
}