wgengine/wgcfg/nmcfg: reduce wireguard reconfig log spam

On the corp tailnet (using Mullvad exit nodes + bunch of expired
devices + subnet routers), these were generating big ~35 KB blobs of
logging regularly.

This logging shouldn't even exist at this level, and should be rate
limited at a higher level, but for now as a bandaid, make it less
spammy.

Updates #cleanup

Change-Id: I0b5e9e6e859f13df5f982cd71cd5af85b73f0c0a
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
patrickod/swtpm-integration-test
Brad Fitzpatrick 3 weeks ago committed by Brad Fitzpatrick
parent 208a32af5b
commit ce10f7c14c

@ -5,7 +5,8 @@
package nmcfg package nmcfg
import ( import (
"bytes" "bufio"
"cmp"
"fmt" "fmt"
"net/netip" "net/netip"
"strings" "strings"
@ -18,16 +19,7 @@ import (
) )
func nodeDebugName(n tailcfg.NodeView) string { func nodeDebugName(n tailcfg.NodeView) string {
name := n.Name() name, _, _ := strings.Cut(cmp.Or(n.Name(), n.Hostinfo().Hostname()), ".")
if name == "" {
name = n.Hostinfo().Hostname()
}
if i := strings.Index(name, "."); i != -1 {
name = name[:i]
}
if name == "" && n.Addresses().Len() != 0 {
return n.Addresses().At(0).String()
}
return name return name
} }
@ -77,10 +69,7 @@ func WGCfg(nm *netmap.NetworkMap, logf logger.Logf, flags netmap.WGConfigFlags,
} }
} }
// Logging buffers var skippedExitNode, skippedSubnetRouter, skippedExpired []tailcfg.NodeView
skippedUnselected := new(bytes.Buffer)
skippedSubnets := new(bytes.Buffer)
skippedExpired := new(bytes.Buffer)
for _, peer := range nm.Peers { for _, peer := range nm.Peers {
if peer.DiscoKey().IsZero() && peer.HomeDERP() == 0 && !peer.IsWireGuardOnly() { if peer.DiscoKey().IsZero() && peer.HomeDERP() == 0 && !peer.IsWireGuardOnly() {
@ -93,16 +82,7 @@ func WGCfg(nm *netmap.NetworkMap, logf logger.Logf, flags netmap.WGConfigFlags,
// anyway, since control intentionally breaks node keys for // anyway, since control intentionally breaks node keys for
// expired peers so that we can't discover endpoints via DERP. // expired peers so that we can't discover endpoints via DERP.
if peer.Expired() { if peer.Expired() {
if skippedExpired.Len() >= 1<<10 { skippedExpired = append(skippedExpired, peer)
if !bytes.HasSuffix(skippedExpired.Bytes(), []byte("...")) {
skippedExpired.WriteString("...")
}
} else {
if skippedExpired.Len() > 0 {
skippedExpired.WriteString(", ")
}
fmt.Fprintf(skippedExpired, "%s/%v", peer.StableID(), peer.Key().ShortString())
}
continue continue
} }
@ -112,28 +92,22 @@ func WGCfg(nm *netmap.NetworkMap, logf logger.Logf, flags netmap.WGConfigFlags,
}) })
cpeer := &cfg.Peers[len(cfg.Peers)-1] cpeer := &cfg.Peers[len(cfg.Peers)-1]
didExitNodeWarn := false didExitNodeLog := false
cpeer.V4MasqAddr = peer.SelfNodeV4MasqAddrForThisPeer().Clone() cpeer.V4MasqAddr = peer.SelfNodeV4MasqAddrForThisPeer().Clone()
cpeer.V6MasqAddr = peer.SelfNodeV6MasqAddrForThisPeer().Clone() cpeer.V6MasqAddr = peer.SelfNodeV6MasqAddrForThisPeer().Clone()
cpeer.IsJailed = peer.IsJailed() cpeer.IsJailed = peer.IsJailed()
for _, allowedIP := range peer.AllowedIPs().All() { for _, allowedIP := range peer.AllowedIPs().All() {
if allowedIP.Bits() == 0 && peer.StableID() != exitNode { if allowedIP.Bits() == 0 && peer.StableID() != exitNode {
if didExitNodeWarn { if didExitNodeLog {
// Don't log about both the IPv4 /0 and IPv6 /0. // Don't log about both the IPv4 /0 and IPv6 /0.
continue continue
} }
didExitNodeWarn = true didExitNodeLog = true
if skippedUnselected.Len() > 0 { skippedExitNode = append(skippedExitNode, peer)
skippedUnselected.WriteString(", ")
}
fmt.Fprintf(skippedUnselected, "%q (%v)", nodeDebugName(peer), peer.Key().ShortString())
continue continue
} else if cidrIsSubnet(peer, allowedIP) { } else if cidrIsSubnet(peer, allowedIP) {
if (flags & netmap.AllowSubnetRoutes) == 0 { if (flags & netmap.AllowSubnetRoutes) == 0 {
if skippedSubnets.Len() > 0 { skippedSubnetRouter = append(skippedSubnetRouter, peer)
skippedSubnets.WriteString(", ")
}
fmt.Fprintf(skippedSubnets, "%v from %q (%v)", allowedIP, nodeDebugName(peer), peer.Key().ShortString())
continue continue
} }
} }
@ -141,14 +115,27 @@ func WGCfg(nm *netmap.NetworkMap, logf logger.Logf, flags netmap.WGConfigFlags,
} }
} }
if skippedUnselected.Len() > 0 { logList := func(title string, nodes []tailcfg.NodeView) {
logf("[v1] wgcfg: skipped unselected default routes from: %s", skippedUnselected.Bytes()) if len(nodes) == 0 {
} return
if skippedSubnets.Len() > 0 { }
logf("[v1] wgcfg: did not accept subnet routes: %s", skippedSubnets) logf("[v1] wgcfg: %s from %d nodes: %s", title, len(nodes), logger.ArgWriter(func(bw *bufio.Writer) {
} const max = 5
if skippedExpired.Len() > 0 { for i, n := range nodes {
logf("[v1] wgcfg: skipped expired peer: %s", skippedExpired) if i == max {
fmt.Fprintf(bw, "... +%d", len(nodes)-max)
return
}
if i > 0 {
bw.WriteString(", ")
}
fmt.Fprintf(bw, "%s (%s)", nodeDebugName(n), n.StableID())
}
}))
} }
logList("skipped unselected exit nodes", skippedExitNode)
logList("did not accept subnet routes", skippedSubnetRouter)
logList("skipped expired peers", skippedExpired)
return cfg, nil return cfg, nil
} }

Loading…
Cancel
Save