Files
OpsLog/internal/steppir/steppir.go
T
rouggy c5c9d355ec fix(logging): name the antenna disagreement, and confirm an outbound send
Two silences from one operator's log.

The SteppIR is not blocked — it is being overruled. Every tune is commanded,
acknowledged on the next poll with the frequency asked for, then replaced on
the poll after by a different one: 21075 asked, 21075 confirmed, 21050
reported, again and again, with the operator tuning once more each time. Two
minutes of that reads as a dead link. It now says what it is, once, when the
motors have stopped and the reported frequency is more than 10 kHz from the
commanded one — a controller quantising to its own grid is not a fault, one
sitting somewhere else entirely is.

UDP outbound had no positive signal at all: only failures were logged. When
an operator sets up an ADIF message to a second logger and nothing arrives,
"OpsLog never sent it" and "the other program did not take it" looked exactly
the same from here — and the first is the common case, because a row created
as an inbound ADIF listener instead of an outbound ADIF message matches
nothing and emits nothing. Successful sends are logged with their destination
and service, and a QSO logged with no outbound row says so once a session.
2026-08-14 17:37:12 +02:00

591 lines
19 KiB
Go
Raw Permalink Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
// 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"
"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{}
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
go c.pollLoop()
return nil
}
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()
}
// 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")
}
p, err := serial.Open(c.tr.COM, &serial.Mode{BaudRate: c.tr.Baud})
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 (attempt %d)", c.target(), 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() {
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
}
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 := io.ReadFull(conn, buf); 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")
}
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()
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'))
}