fix(tun): summarize unrouted-packet floods; log peer stream lifetimes

An unrouted destination under load produced one warn line per packet,
burying the event that caused the routing gap. Count misses and report
the total once per window instead; the first miss is still logged at
once.

Also log how long a peer stream lived and how much arrived on it when
it ends, so a dying peer's story (failed to connect vs failed mid-
transfer) is visible without correlating route drops.

Also ignore .memory/.
This commit is contained in:
ginuerzh
2026-10-07 01:18:38 +00:00
parent 4bbf81c9f4
commit 9ec8bdbfeb
3 changed files with 109 additions and 1 deletions
+1
View File
@@ -15,6 +15,7 @@ package-lock.json
.codegraph/
.claude/
.remember/
.memory/
.build/
__pycache__/
+52 -1
View File
@@ -8,6 +8,7 @@ import (
"io"
"net"
"sync"
"time"
"github.com/songgao/water/waterutil"
"golang.org/x/net/ipv4"
@@ -165,6 +166,15 @@ type p2pHub struct {
// wmu serializes device writes; see above. Reads are not locked because
// there is only one of them, and it is not this lock's business.
wmu sync.Mutex
// dropMu guards the unrouted-packet tally that countUnrouted keeps, so a
// flood of discards costs one counter increment per packet and one log line
// per window instead of one line per packet.
dropMu sync.Mutex
dropCount int
dropDst string
dropSince time.Time
}
func newP2PHub(device io.ReadWriter, router *peerRouter, ownNets []net.IPNet, warn func(string)) *p2pHub {
@@ -219,12 +229,53 @@ func (h *p2pHub) dispatch(pkt []byte) {
// registration handshake is gated on network == "udp" (client.go), and a
// p2p link is "ip", so a spoke configured with keepalive:0 never
// registers at all.
h.warnf("no route for %s, packet discarded", dst)
//
// Counted rather than logged per packet: an unrouted destination under
// load produces one line per packet, which buries every other line and
// turns a routing gap into a log flood that hides the event that caused
// it. The first miss is logged immediately (a spoke that never registers
// must still be visible), and after that the summary carries the count and
// the span it covers.
h.countUnrouted(dst)
case err != nil:
h.warnf("route %s: %v", dst, err)
}
}
// unroutedWindow is how long unrouted packets are counted before the summary is
// reported. Long enough that a brief gap is one line, short enough to appear
// within the same log window as the failure that caused it.
const unroutedWindow = 5 * time.Second
// countUnrouted records one unrouted destination and reports the running total
// at most once per window. dst is reported rather than counted per address: a
// hub's unrouted traffic is normally one peer (the one whose route is missing),
// and a map of addresses would be a second routing table to keep honest.
func (h *p2pHub) countUnrouted(dst net.IP) {
h.dropMu.Lock()
now := time.Now()
if h.dropSince.IsZero() {
h.dropSince = now
h.dropDst = dst.String()
h.dropCount = 1
h.dropMu.Unlock()
h.warnf("no route for %s, packet discarded", dst)
return
}
h.dropCount++
// The window only restarts on a report, so a continuous flood reports once
// per window instead of once per packet.
if now.Sub(h.dropSince) < unroutedWindow {
h.dropMu.Unlock()
return
}
n, since, d := h.dropCount, h.dropSince, h.dropDst
h.dropSince, h.dropCount = now, 0
h.dropMu.Unlock()
h.warnf("no route for %s, %d packets discarded in %s", d, n,
time.Since(since).Round(time.Millisecond).String())
}
// fromSpoke handles one datagram from one peer: a keepalive is answered on the
// peer it arrived from, anything else is the device's.
func (h *p2pHub) fromSpoke(s *peerStream, pkt []byte) error {
+56
View File
@@ -3,8 +3,12 @@ package tun
import (
"context"
"errors"
"fmt"
"io"
"net"
"strings"
"sync"
"time"
"github.com/go-gost/core/handler"
"github.com/go-gost/core/logger"
@@ -125,21 +129,36 @@ func (h *p2pHandler) Handle(ctx context.Context, conn net.Conn, opts ...handler.
defer h.hub.peerGone(s)
// The read error is this peer's story, and it used to leave none: the loop
// returned it, service.Serve logged "EOF" at debug, and the only trace of a
// peer that had been carrying megabytes before it stopped was a route being
// dropped. Counting what arrived makes the log answer that on its own — a peer
// that dies having read nothing failed to connect, one that dies mid-transfer
// failed in transit, and the difference is the whole diagnosis.
started := time.Now()
var frames, bytes int64
var b [MaxMessageSize]byte
for {
select {
case <-ctx.Done():
h.logStreamEnd(s, started, frames, bytes, ctx.Err())
return ctx.Err()
default:
}
n, err := conn.Read(b[:])
if n > 0 {
frames++
bytes += int64(n)
}
if err != nil {
// Returned as-is, and that is the whole convention: a stream that ends
// is io.EOF, a closed conn is net.ErrClosed, and a torn-down context is
// context.Canceled — service.Serve reads each of those as an ordinary
// end and logs it at debug, while anything else is a failure. Wrapping
// them here would put a normal reconnect in someone's error log.
h.logStreamEnd(s, started, frames, bytes, err)
return err
}
if n == 0 {
@@ -149,12 +168,49 @@ func (h *p2pHandler) Handle(ctx context.Context, conn net.Conn, opts ...handler.
// anything else to the device under the hub's write lock; the hub logs
// its own routing warnings, so a failure here is the write itself.
if err := h.hub.fromSpoke(s, b[:n]); err != nil {
h.logStreamEnd(s, started, frames, bytes, err)
h.log.Warnf("peer %s: %v", s.key, err)
return err
}
}
}
// logStreamEnd reports how long a peer's stream lived, how much arrived on it,
// and what ended it. The level follows the cause rather than the volume: a peer
// that closed its stream, or whose context was cancelled, is the ordinary way a
// hub learns a spoke left, and it stays at debug; anything else is a failure the
// operator would otherwise only see as silence.
func (h *p2pHandler) logStreamEnd(s *peerStream, started time.Time, frames, bytes int64, err error) {
fields := []any{
"peer", s.key,
"age", time.Since(started).Round(time.Millisecond).String(),
"frames", frames,
"bytes", bytes,
}
if err != nil {
fields = append(fields, "error", err)
}
if err == nil || errors.Is(err, io.EOF) || errors.Is(err, net.ErrClosed) || errors.Is(err, context.Canceled) {
h.log.Debugf("peer stream ended: %s", formatFields(fields))
return
}
h.log.Warnf("peer stream failed: %s", formatFields(fields))
}
// formatFields renders slog-style fields as "k=v k=v" for the logger interface
// this handler is given. The hub's other lines use printf formatting, so the
// counters are assembled here rather than at each call site.
func formatFields(fields []any) string {
var b strings.Builder
for i := 0; i+1 < len(fields); i += 2 {
if i > 0 {
b.WriteByte(' ')
}
fmt.Fprintf(&b, "%v=%v", fields[i], fields[i+1])
}
return b.String()
}
// Close stops the device reader. The device is what the reader is blocked in, so
// closing it is the stop; the loop's own error is logged where it ends rather
// than returned, since a handler is closed by its service, not by its peer.