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
parent 7470ebf47e
commit c5c9d355ec
5 changed files with 141 additions and 3 deletions
@@ -9,7 +9,9 @@
      "Serial ports: a port claimed by two devices in the Windows port map was listed twice in every port dropdown, and showed as “COM3COM3”. Listed once now, and in natural order — COM4 between COM3 and COM8, not after COM9.",
      "Motorized antenna: an antenna that lost its serial port stopped answering with nothing at all in the log. Every reason it fails to start or reconnect is now written down, once.",
      "UDP: an ADIF listener sharing a port with a WSJT source logged a line per decode — hundreds of them. It now says what the traffic really is, once, and how to fix it.",
-      "QSL Manager, paper QSL: the route is set per direction — bureau, direct or electronic, beside the sent status and beside the received one — and applies to the whole selection at once."
+      "QSL Manager, paper QSL: the route is set per direction — bureau, direct or electronic, beside the sent status and beside the received one — and applies to the whole selection at once.",
+      "Motorized antenna: when the controller settles somewhere other than where it was told, the log says so — that reads as “the antenna stopped responding” otherwise.",
+      "UDP: an outbound message now logs that it was sent, and a logged QSO with no outbound ADIF row configured says so once."
    ],
    "fr": [
      "Envoi de spot : le commentaire porte désormais les références de diplôme après le mode — celles que vous avez attribuées (POTA, SOTA, IOTA…), pas le DXCC, la zone et le préfixe que chacun déduit de l’indicatif. Un auto-spot porte VOS références d’activation.",
@@ -18,7 +20,9 @@
      "Ports série : un port revendiqué par deux périphériques dans la table Windows apparaissait en double dans toutes les listes, et s’affichait « COM3COM3 ». Une seule fois désormais, et dans l’ordre naturel — COM4 entre COM3 et COM8, pas après COM9.",
      "Antenne motorisée : une antenne ayant perdu son port série cessait de répondre sans rien laisser dans le journal. Chaque raison d’un démarrage ou d’une reconnexion manquée est désormais écrite, une fois.",
      "UDP : un écouteur ADIF partageant un port avec une source WSJT écrivait une ligne par décodage — des centaines. Il dit maintenant ce qu’est vraiment ce trafic, une fois, et comment le corriger.",
-      "Gestionnaire QSL, QSL papier : la voie se règle par sens — bureau, direct ou électronique, à côté du statut envoyé et à côté du statut reçu — et s’applique à toute la sélection d’un coup."
+      "Gestionnaire QSL, QSL papier : la voie se règle par sens — bureau, direct ou électronique, à côté du statut envoyé et à côté du statut reçu — et s’applique à toute la sélection d’un coup.",
+      "Antenne motorisée : quand le contrôleur se fixe ailleurs que là où on l’a envoyé, le journal le dit — sans quoi cela ressemble à une antenne qui ne répond plus.",
+      "UDP : un message sortant inscrit désormais son envoi dans le journal, et un QSO enregistré sans ligne ADIF sortante le signale une fois."
    ]
  },
  {
@@ -86,12 +86,35 @@ func (m *Manager) EmitLoggedADIF(adif string) {
 	if strings.TrimSpace(adif) == "" {
 		return
 	}
-	for _, c := range m.Outbound(ServiceDBUpdated) {
+	rows := m.Outbound(ServiceDBUpdated)
+	if len(rows) == 0 {
+		// Said once per session, not per QSO. An operator who configured a second
+		// logger and sees nothing arrive needs to know the difference between "we
+		// sent it" and "there was nothing to send to" — and the usual cause is a
+		// row created as an inbound ADIF listener instead of an outbound message.
+		m.noADIFOnce.Do(func() {
+			applog.Printf("udp: a QSO was logged but no outbound \"ADIF message\" row is enabled — " +
+				"nothing is forwarded to another logger")
+		})
+		return
+	}
+	for _, c := range rows {
 		m.sendTo(c, []byte(adif))
 	}
 }

 // sendTo resolves the row's destination (host:port) and fires one datagram.
+//
+// A successful send is logged, not just a failure. UDP has no delivery report:
+// when an operator says "I set up an ADIF message to Logger32 on port 2250 and
+// nothing arrives", the only thing that separates "OpsLog never sent it" from
+// "the other program did not take it" is a line saying we sent. Without one,
+// both look identical from here — and the first is far more common, because a
+// row created as an INBOUND ADIF listener rather than an OUTBOUND ADIF message
+// matches nothing and emits nothing, in silence.
+//
+// Rate is not a concern: these fire on a QSO being logged or a frequency
+// change, not per packet on a socket.
 func (m *Manager) sendTo(c Config, payload []byte) {
 	host := strings.TrimSpace(c.DestinationIP)
 	if host == "" {
@@ -100,5 +123,7 @@ func (m *Manager) sendTo(c Config, payload []byte) {
 	dst := fmt.Sprintf("%s:%d", host, c.Port)
 	if err := SendUDP(dst, payload); err != nil {
 		applog.Printf("udp: [%s] outbound send to %s failed: %v", c.Name, dst, err)
+		return
 	}
+	applog.Printf("udp: [%s] sent %d bytes to %s (%s)", c.Name, len(payload), dst, c.ServiceType)
 }
@@ -497,6 +497,10 @@ type Manager struct {
 	repo *Repo
 	out  chan Event

+	// noADIFOnce keeps the "nothing to forward to" note to one line a session
+	// rather than one per QSO logged.
+	noADIFOnce sync.Once
+
 	mu       sync.Mutex
 	inbound  map[int64]*Server
 	outbound []Config
@@ -0,0 +1,50 @@
+package steppir
+
+import "testing"
+
+// An operator's log read as "the antenna stops responding": every tune was
+// commanded, acknowledged with the requested frequency on the next poll, then
+// replaced on the poll after by a different one — 21075 asked, 21075 confirmed,
+// 21050 reported — with the operator tuning again each time. Nothing in the log
+// named that, so it looked like a dead link.
+func TestCheckDriftReportsOnceAndRecovers(t *testing.T) {
+	c := &Client{}
+	c.lastSetKHz = 21075
+
+	// Where it was asked to go: nothing to say.
+	c.checkDrift(&Status{Frequency: 21075})
+	if c.lastDriftKHz != 0 {
+		t.Errorf("a controller on frequency was reported as drifting (%d)", c.lastDriftKHz)
+	}
+	// Its own grid is not a fault.
+	c.checkDrift(&Status{Frequency: 21070})
+	if c.lastDriftKHz != 0 {
+		t.Errorf("%d kHz is within tolerance and was reported", 21070)
+	}
+	// Somewhere else entirely: recorded, so it is said once.
+	c.checkDrift(&Status{Frequency: 21050})
+	if c.lastDriftKHz != 21050 {
+		t.Errorf("lastDriftKHz = %d, want 21050", c.lastDriftKHz)
+	}
+	// Still there on the next poll: nothing new to say, and the marker stands.
+	c.checkDrift(&Status{Frequency: 21050})
+	if c.lastDriftKHz != 21050 {
+		t.Errorf("lastDriftKHz = %d after a repeat, want it unchanged", c.lastDriftKHz)
+	}
+	// Back where it belongs: the marker clears, so the next divergence is said.
+	c.checkDrift(&Status{Frequency: 21075})
+	if c.lastDriftKHz != 0 {
+		t.Errorf("lastDriftKHz = %d after recovery, want 0", c.lastDriftKHz)
+	}
+}
+
+// A frequency read while the elements are travelling is not a disagreement, it
+// is an antenna on its way — reporting it would cry wolf on every single tune.
+func TestCheckDriftIgnoresMovingMotors(t *testing.T) {
+	c := &Client{}
+	c.lastSetKHz = 21075
+	c.checkDrift(&Status{Frequency: 21000, MotorsMoving: 1})
+	if c.lastDriftKHz != 0 {
+		t.Errorf("a moving antenna was reported as drifting (%d)", c.lastDriftKHz)
+	}
+}
@@ -102,6 +102,10 @@ type Client struct {
 	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
@@ -269,10 +273,61 @@ func (c *Client) pollLoop() {
 			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.