fix(logging): say why the antenna stopped and what the ADIF port is receiving

Two problems from one operator's log, both of them the log's fault.

SteppIR. The last line about it is "status query failed, reconnecting: Port
has been closed" and then nothing — for the rest of the session. The poll loop
does retry every two seconds, but a failed open was a bare `continue`: no line,
ever. And startUltrabeam had three silent ways out — settings unreadable, the
antenna turned off, no port or host configured — so a cleared field and a lost
adapter produced exactly the same evidence, which is none. Both now say what
happened, with the port or host named. Reopen failures are reported three
times and then throttled (a port that is gone stays gone), and the recovery
says how many attempts it took.

FLDIGI. Four hundred "ADIF payload ignored" lines and nothing else legible.
The cause is in the same log: two inbound listeners on the SAME multicast
group and port, 239.255.0.1:2237 — one WSJT (MSHV), one ADIF (FLDIGI). Every
WSJT-X packet is delivered to both, and an FT8 cycle is dozens of decodes
every fifteen seconds; the bursts in the log are exactly 15 s apart. The ADIF
listener now checks for the WSJT-X magic and says so once, with what to do
about it, instead of rejecting each packet in writing. Anything else is
described a few times with its payload and then goes quiet.
This commit is contained in:
2026-08-14 16:24:06 +02:00
parent 61006d8155
commit 2cd1274975
5 changed files with 151 additions and 5 deletions
+21 -2
View File
@@ -15172,13 +15172,32 @@ func (a *App) startUltrabeam() {
go a.motorAnt.Stop() go a.motorAnt.Stop()
a.motorAnt = nil a.motorAnt = nil
} }
// Every way out of here used to be silent, which is how an antenna that had
// been working for three minutes went off the air with NOTHING in the log
// after the disconnection — the operator could not tell a deliberate stop
// from a lost port from a cleared setting.
s, err := a.GetUltrabeamSettings() s, err := a.GetUltrabeamSettings()
if err != nil || !s.Enabled { if err != nil {
applog.Printf("antenna: not started — settings unavailable: %v", err)
return
}
if !s.Enabled {
applog.Printf("antenna: not started — turned off in Settings")
return return
} }
c := newMotorClient(s) c := newMotorClient(s)
if c == nil { if c == nil {
return // not configured (missing host/COM) if s.Transport == "serial" {
applog.Printf("antenna: %s not started — no serial port configured", s.Type)
} else {
applog.Printf("antenna: %s not started — no host configured", s.Type)
}
return
}
if s.Transport == "serial" {
applog.Printf("antenna: %s starting on %s @ %d baud", s.Type, s.COM, s.Baud)
} else {
applog.Printf("antenna: %s starting on %s:%d", s.Type, s.Host, s.Port)
} }
a.motorAnt = c a.motorAnt = c
_ = a.motorAnt.Start() _ = a.motorAnt.Start()
+6 -2
View File
@@ -6,13 +6,17 @@
"Send Spot: the comment now carries the award references after the mode — the ones you assigned (POTA, SOTA, IOTA…), not the DXCC, zone and prefix every reader works out from the callsign. A self-spot carries your OWN activation references instead.", "Send Spot: the comment now carries the award references after the mode — the ones you assigned (POTA, SOTA, IOTA…), not the DXCC, zone and prefix every reader works out from the callsign. A self-spot carries your OWN activation references instead.",
"Modes: a fresh install now starts with SSB, CW, FT8, FT4, FT2, RTTY, PSK31 and FM. AM and DIGITALVOICE stay in the available list but are no longer selected by default.", "Modes: a fresh install now starts with SSB, CW, FT8, FT4, FT2, RTTY, PSK31 and FM. AM and DIGITALVOICE stay in the available list but are no longer selected by default.",
"Chase new: a panel listing the stations PSK Reporter is hearing within about 300 km of you that are new against your log — on FT8, FT4, FT2, PSK31 and RTTY, and only on the bands you have selected. One badge per row, the most valuable first (entity, band, mode, slot, prefix, square), with a filter for each, a toolbar button to show it and a cross to close it. Click a row to put the callsign in the entry and tune the rig.", "Chase new: a panel listing the stations PSK Reporter is hearing within about 300 km of you that are new against your log — on FT8, FT4, FT2, PSK31 and RTTY, and only on the bands you have selected. One badge per row, the most valuable first (entity, band, mode, slot, prefix, square), with a filter for each, a toolbar button to show it and a cross to close it. Click a row to put the callsign in the entry and tune the rig.",
"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." "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."
], ],
"fr": [ "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 lindicatif. Un auto-spot porte VOS références dactivation.", "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 lindicatif. Un auto-spot porte VOS références dactivation.",
"Modes : une installation neuve démarre avec SSB, CW, FT8, FT4, FT2, RTTY, PSK31 et FM. AM et DIGITALVOICE restent dans la liste disponible mais ne sont plus sélectionnés par défaut.", "Modes : une installation neuve démarre avec SSB, CW, FT8, FT4, FT2, RTTY, PSK31 et FM. AM et DIGITALVOICE restent dans la liste disponible mais ne sont plus sélectionnés par défaut.",
"Chasse au nouveau : un panneau listant les stations que PSK Reporter entend à moins de 300 km de chez vous et qui sont nouvelles par rapport à votre log — en FT8, FT4, FT2, PSK31 et RTTY, et seulement sur les bandes que vous avez sélectionnées. Une seule indication par ligne, la plus précieuse dabord (entité, bande, mode, créneau, préfixe, carré), avec un filtre pour chacune, un bouton dans la barre pour lafficher et une croix pour le fermer. Un clic met lindicatif en saisie et accorde la radio.", "Chasse au nouveau : un panneau listant les stations que PSK Reporter entend à moins de 300 km de chez vous et qui sont nouvelles par rapport à votre log — en FT8, FT4, FT2, PSK31 et RTTY, et seulement sur les bandes que vous avez sélectionnées. Une seule indication par ligne, la plus précieuse dabord (entité, bande, mode, créneau, préfixe, carré), avec un filtre pour chacune, un bouton dans la barre pour lafficher et une croix pour le fermer. Un clic met lindicatif en saisie et accorde la radio.",
"Ports série : un port revendiqué par deux périphériques dans la table Windows apparaissait en double dans toutes les listes, et saffichait « COM3COM3 ». Une seule fois désormais, et dans lordre naturel — COM4 entre COM3 et COM8, pas après COM9." "Ports série : un port revendiqué par deux périphériques dans la table Windows apparaissait en double dans toutes les listes, et saffichait « COM3COM3 ». Une seule fois désormais, et dans lordre 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 dun démarrage ou dune 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 quest vraiment ce trafic, une fois, et comment le corriger."
] ]
}, },
{ {
@@ -0,0 +1,40 @@
package udp
import (
"encoding/binary"
"testing"
)
// An operator's log arrived with four hundred identical "ADIF payload ignored"
// lines and nothing else legible: two inbound listeners were configured on the
// SAME multicast group and port, one WSJT and one ADIF, so every WSJT-X decode
// was delivered to both and the ADIF one rejected each in writing. An FT8 cycle
// is dozens of decodes every fifteen seconds.
//
// The listener has to recognise that traffic and say what it is — once.
func TestIgnoredADIFStaysBounded(t *testing.T) {
s := &Server{cfg: Config{Name: "FLDIGI", Port: 2237}}
// A WSJT-X packet: magic first. One line is the whole diagnosis, so the
// counter is pushed past the cap immediately.
pkt := make([]byte, 16)
binary.BigEndian.PutUint32(pkt[:4], wsjtMagic)
s.noteIgnoredADIF(pkt)
if s.badPkts <= maxBadPktDumps {
t.Errorf("badPkts = %d — WSJT traffic should silence the listener at once", s.badPkts)
}
// Anything else is described a few times before going quiet, so an ordinary
// keep-alive does not get the same one-line treatment as a real diagnosis.
s2 := &Server{cfg: Config{Name: "FLDIGI", Port: 2237}}
s2.noteIgnoredADIF([]byte("keep-alive"))
if s2.badPkts > maxBadPktDumps {
t.Errorf("one unusable payload silenced the listener (badPkts = %d)", s2.badPkts)
}
for i := 0; i < 50; i++ {
s2.noteIgnoredADIF([]byte("keep-alive"))
}
if s2.badPkts <= maxBadPktDumps {
t.Errorf("badPkts = %d — the throttle never engaged", s2.badPkts)
}
}
+40 -1
View File
@@ -2,6 +2,7 @@ package udp
import ( import (
"context" "context"
"encoding/binary"
"fmt" "fmt"
"net" "net"
"regexp" "regexp"
@@ -268,6 +269,44 @@ func (s *Server) logBadPacket(kind string, remote *net.UDPAddr, pkt []byte, err
} }
} }
// noteIgnoredADIF reports a payload the ADIF listener could not use, ONCE per
// cause and then quietly.
//
// This used to log a line per datagram. An operator's log arrived with four
// hundred identical "ADIF payload ignored" lines and nothing else legible: two
// inbound listeners were configured on the SAME multicast group and port
// (239.255.0.1:2237, one WSJT and one ADIF), so every WSJT-X decode packet was
// delivered to both, and the ADIF one rejected each of them in writing. An FT8
// cycle is dozens of decodes every fifteen seconds.
//
// So the WSJT-X magic number is checked here. When it matches, the payload is
// not "chatter" — it is a specific, fixable misconfiguration, and saying which
// is the difference between a log the operator can act on and one they cannot.
func (s *Server) noteIgnoredADIF(pkt []byte) {
s.mu.Lock()
s.badPkts++
n := s.badPkts
s.mu.Unlock()
if n > maxBadPktDumps {
return
}
if len(pkt) >= 4 && binary.BigEndian.Uint32(pkt[:4]) == wsjtMagic {
applog.Printf("udp: [%s] this is WSJT-X traffic, not ADIF — port %d is shared with a WSJT source; "+
"give the ADIF forwarder (JTAlert / GridTracker) its own port, or set this listener's service to WSJT\n",
s.cfg.Name, s.cfg.Port)
// One line is the whole diagnosis: nothing is gained by counting to five.
s.mu.Lock()
s.badPkts = maxBadPktDumps + 1
s.mu.Unlock()
return
}
applog.Printf("udp: [%s] ADIF payload ignored (no <call:>/<eor>) — %s\n", s.cfg.Name, describePacket(pkt))
if n == maxBadPktDumps {
applog.Printf("udp: [%s] further unusable payloads on port %d will not be logged\n",
s.cfg.Name, s.cfg.Port)
}
}
func (s *Server) handle(pkt []byte, remote *net.UDPAddr) { func (s *Server) handle(pkt []byte, remote *net.UDPAddr) {
ev := Event{ConfigID: s.cfg.ID, Service: s.cfg.ServiceType, Source: remote.String()} ev := Event{ConfigID: s.cfg.ID, Service: s.cfg.ServiceType, Source: remote.String()}
switch s.cfg.ServiceType { switch s.cfg.ServiceType {
@@ -338,7 +377,7 @@ func (s *Server) handle(pkt []byte, remote *net.UDPAddr) {
text := string(pkt) text := string(pkt)
low := strings.ToLower(text) low := strings.ToLower(text)
if !strings.Contains(low, "<call:") || !strings.Contains(low, "<eor") { if !strings.Contains(low, "<call:") || !strings.Contains(low, "<eor") {
applog.Printf("udp: [%s] ADIF payload ignored (no <call:>/<eor>)\n", s.cfg.Name) s.noteIgnoredADIF(pkt)
return return
} }
ev.LoggedADIF = text ev.LoggedADIF = text
+44
View File
@@ -88,6 +88,10 @@ type Client struct {
connMu sync.Mutex connMu sync.Mutex
conn io.ReadWriteCloser 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 // ioMu serialises EVERY exchange on the shared connection — a status query
// (write "?A" then read 11 bytes) and a command write must never interleave, // (write "?A" then read 11 bytes) and a command write must never interleave,
@@ -187,6 +191,35 @@ func (c *Client) open() (io.ReadWriteCloser, error) {
} }
} }
// 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() { func (c *Client) pollLoop() {
ticker := time.NewTicker(2 * time.Second) ticker := time.NewTicker(2 * time.Second)
defer ticker.Stop() defer ticker.Stop()
@@ -201,8 +234,19 @@ func (c *Client) pollLoop() {
if err != nil { if err != nil {
c.connMu.Unlock() c.connMu.Unlock()
c.setDisconnected() 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 continue
} }
if c.openFails > 0 {
log.Printf("steppir: reconnected after %d failed attempt(s)", c.openFails)
c.openFails = 0
}
c.conn = conn c.conn = conn
} }
c.connMu.Unlock() c.connMu.Unlock()