diff --git a/.gitignore b/.gitignore index ba84709..36ae8c2 100644 --- a/.gitignore +++ b/.gitignore @@ -15,6 +15,7 @@ package-lock.json .codegraph/ .claude/ .remember/ +.memory/ .build/ __pycache__/ diff --git a/handler/tun/p2p.go b/handler/tun/p2p.go index 2bc60bd..b0ef705 100644 --- a/handler/tun/p2p.go +++ b/handler/tun/p2p.go @@ -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 { diff --git a/handler/tun/p2phandler.go b/handler/tun/p2phandler.go index 209f779..16c90ee 100644 --- a/handler/tun/p2phandler.go +++ b/handler/tun/p2phandler.go @@ -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.