feat(udp): show the packet behind a parse error, and stop repeating it

"WSJT parse error: bad magic 0x3132372e" named neither the sender nor the
payload, so there was nothing to act on — even though those four bytes are
ASCII "127.", i.e. some program broadcasting an address on a port expecting
WSJT-X binary.

The line now carries the remote address, the size, a printable preview and a
hex dump of the first 96 bytes. Text senders are readable at a glance; a
genuinely binary payload still shows its bytes.

And it stops after five. The reported case wrote that line about 150 times a
second: a permanently misconfigured port would fill the 10 MB rotating log with
one repeated sentence and bury every other piece of evidence — the log's whole
purpose. The fifth line names the two things worth checking, the sender and the
service type.

N1MM's parse error goes through the same path; it had no packet detail either.
This commit is contained in:
2026-08-09 07:59:51 +02:00
parent 40f5960c76
commit a0f7f2abf0
3 changed files with 113 additions and 2 deletions
@@ -0,0 +1,43 @@
package udp
import (
"strings"
"testing"
)
// The diagnostic that matters: a text payload arriving on a WSJT port must be
// READABLE in the log. "bad magic 0x3132372e" alone told the operator nothing —
// those four bytes are ASCII "127.", i.e. some program broadcasting an address
// where WSJT-X binary was expected.
func TestDescribePacketShowsTextAndHex(t *testing.T) {
got := describePacket([]byte("127.0.0.1:4532"))
for _, want := range []string{`14 bytes`, `"127.0.0.1:4532"`, `31 32 37 2e`} {
if !strings.Contains(got, want) {
t.Errorf("describePacket missing %q\ngot: %s", want, got)
}
}
}
// Binary stays inspectable: unprintable bytes become dots in the preview and
// the hex carries the real values.
func TestDescribePacketHandlesBinary(t *testing.T) {
got := describePacket([]byte{0xad, 0xbc, 0xcb, 0xda, 0x00})
if !strings.Contains(got, `"....."`) || !strings.Contains(got, "ad bc cb da 00") {
t.Errorf("binary preview wrong: %s", got)
}
}
// A long datagram is truncated, and says so, rather than dumping a whole packet
// into the log on every line.
func TestDescribePacketTruncates(t *testing.T) {
got := describePacket([]byte(strings.Repeat("A", 300)))
if !strings.Contains(got, "300 bytes") {
t.Errorf("lost the real length: %s", got)
}
if !strings.Contains(got, "…") {
t.Errorf("truncation not marked: %s", got)
}
if strings.Count(got, "41 ") > 96 {
t.Errorf("hex not capped: %s", got)
}
}
+68 -2
View File
@@ -94,6 +94,47 @@ type Server struct {
// id is distinct whenever there is more than one.
dialHz map[string]int64
lastDX string // WSJT: last non-empty DX Call seen, to detect a clear
// badPkts counts datagrams this listener could not parse, so the diagnostic
// dump below stays bounded. A misconfigured port is not a one-off: the
// sender that produced "bad magic 0x3132372e" put out ~150 packets a second,
// which fills the whole rotating log with the same line and buries the
// evidence of anything else.
badPkts int
}
// maxBadPktDumps is how many unparseable datagrams a listener describes in full
// before going quiet. Enough to identify the sender and the payload; few enough
// that a permanently misconfigured port costs a handful of lines, not a log.
const maxBadPktDumps = 5
// describePacket renders a datagram for the log: its size, a printable preview
// and the first bytes in hex.
//
// Both forms, deliberately. "bad magic 0x3132372e" is already readable as ASCII
// "127." to someone who thinks to decode it — and that one fact (the sender is
// emitting text, not WSJT-X binary) is the whole diagnosis. The hex stays for
// the case where the payload really is binary and the preview shows nothing.
func describePacket(pkt []byte) string {
const maxShown = 96
head := pkt
if len(head) > maxShown {
head = head[:maxShown]
}
var text, hex strings.Builder
for _, b := range head {
if b >= 0x20 && b < 0x7f {
text.WriteByte(b)
} else {
text.WriteByte('.')
}
fmt.Fprintf(&hex, "%02x ", b)
}
more := ""
if len(pkt) > maxShown {
more = "…"
}
return fmt.Sprintf("%d bytes | text %q%s | hex %s%s", len(pkt), text.String(), more, strings.TrimSpace(hex.String()), more)
}
func newServer(cfg Config, out chan<- Event) *Server {
@@ -201,13 +242,38 @@ func (s *Server) run() {
}
}
// logBadPacket reports a datagram this listener could not parse, with enough of
// it to identify the sender — then falls silent.
//
// The point is the SENDER: an unparseable packet on a WSJT port almost always
// means another program is broadcasting on it, or the service type is wrong for
// what is actually arriving. The remote address names the culprit, and the
// payload preview says what it really is. Neither was logged before, so the
// operator saw only a magic number repeated a few hundred times a second.
func (s *Server) logBadPacket(kind string, remote *net.UDPAddr, pkt []byte, err error) {
s.mu.Lock()
s.badPkts++
n := s.badPkts
s.mu.Unlock()
if n > maxBadPktDumps {
return
}
applog.Printf("udp: [%s] %s parse error from %s: %v — %s\n",
s.cfg.Name, kind, remote, err, describePacket(pkt))
if n == maxBadPktDumps {
applog.Printf("udp: [%s] further unparseable packets on port %d will not be logged — "+
"check that the sender belongs on this port and that the service type matches\n",
s.cfg.Name, s.cfg.Port)
}
}
func (s *Server) handle(pkt []byte, remote *net.UDPAddr) {
ev := Event{ConfigID: s.cfg.ID, Service: s.cfg.ServiceType, Source: remote.String()}
switch s.cfg.ServiceType {
case ServiceWSJT:
w, ok, err := ParseWSJT(pkt)
if err != nil {
applog.Printf("udp: [%s] WSJT parse error: %v\n", s.cfg.Name, err)
s.logBadPacket("WSJT", remote, pkt, err)
return
}
if !ok {
@@ -321,7 +387,7 @@ func (s *Server) handle(pkt []byte, remote *net.UDPAddr) {
case ServiceN1MM:
adifText, ok, err := ParseN1MM(pkt)
if err != nil {
applog.Printf("udp: [%s] N1MM parse error: %v\n", s.cfg.Name, err)
s.logBadPacket("N1MM", remote, pkt, err)
return
}
if !ok {