wgengine/magicsock: make component debug logging include disco logs

Updates #1548

Change-Id: Ie70b4930670ca7a0f225d585afbb87048aefc965
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>

wgengine/magicsock/debugknobs.go

@@ -12,9 +12,9 @@ import (
 // Various debugging and experimental tweakables, set by environment
 // variable.
 var (
-	// debugDisco prints verbose logs of active discovery events as
+	// debugDiscoEnv prints verbose logs of active discovery events as
 	// they happen.
-	debugDisco = envknob.RegisterBool("TS_DEBUG_DISCO")
+	debugDiscoEnv = envknob.RegisterBool("TS_DEBUG_DISCO")
 	// debugPeerMap prints verbose logs of changes to the peermap.
 	debugPeerMap = envknob.RegisterBool("TS_DEBUG_MAGICSOCK_PEERMAP")
 	// debugOmitLocalAddresses removes all local interface addresses

wgengine/magicsock/endpoint.go

@@ -613,7 +613,7 @@ func (de *endpoint) discoPingTimeout(txid stun.TxID) {
 	if !ok {
 		return
 	}
-	if debugDisco() || !de.bestAddr.IsValid() || mono.Now().After(de.trustBestAddrUntil) {
+	if de.c.debugDisco() || !de.bestAddr.IsValid() || mono.Now().After(de.trustBestAddrUntil) {
 		de.c.dlogf("[v1] magicsock: disco: timeout waiting for pong %x from %v (%v, %v)", txid[:6], sp.to, de.publicKey.ShortString(), de.discoShort())
 	}
 	de.removeSentDiscoPingLocked(txid, sp)

wgengine/magicsock/magicsock.go

@@ -310,6 +310,13 @@ func (c *Conn) dlogf(format string, a ...any) {
 	}
 }
 
+// debugDisco reports whether we should log verbose things about disco packets.
+// It returns true if either the disco-specific environment variable or the
+// component debug logging is enabled.
+func (c *Conn) debugDisco() bool {
+	return debugDiscoEnv() || c.debugLogging.Load()
+}
+
 // Options contains options for Listen.
 type Options struct {
 	// Logf optionally provides a log function to use.
@@ -1273,7 +1280,7 @@ func (c *Conn) sendDiscoMessage(dst netip.AddrPort, dstKey key.NodePublic, dstDi
 	pkt = append(pkt, box...)
 	sent, err = c.sendAddr(dst, dstKey, pkt)
 	if sent {
-		if logLevel == discoLog || (logLevel == discoVerboseLog && debugDisco()) {
+		if logLevel == discoLog || (logLevel == discoVerboseLog && c.debugDisco()) {
 			node := "?"
 			if !dstKey.IsZero() {
 				node = dstKey.ShortString()
@@ -1345,7 +1352,7 @@ func (c *Conn) handleDiscoMessage(msg []byte, src netip.AddrPort, derpNodeSrc ke
 	if c.closed {
 		return
 	}
-	if debugDisco() {
+	if c.debugDisco() {
 		c.logf("magicsock: disco: got disco-looking frame from %v via %s len %v", sender.ShortString(), via, len(msg))
 	}
 	if c.privateKey.IsZero() {
@@ -1356,7 +1363,7 @@ func (c *Conn) handleDiscoMessage(msg []byte, src netip.AddrPort, derpNodeSrc ke
 
 	if !c.peerMap.anyEndpointForDiscoKey(sender) {
 		metricRecvDiscoBadPeer.Add(1)
-		if debugDisco() {
+		if c.debugDisco() {
 			c.logf("magicsock: disco: ignoring disco-looking frame, don't know endpoint for %v", sender.ShortString())
 		}
 		return
@@ -1382,7 +1389,7 @@ func (c *Conn) handleDiscoMessage(msg []byte, src netip.AddrPort, derpNodeSrc ke
 		// group of messages. Don't log in normal case.
 		// Callers may choose to pass on to wireguard, in case
 		// it's actually a wireguard packet (super unlikely, but).
-		if debugDisco() {
+		if c.debugDisco() {
 			c.logf("magicsock: disco: failed to open naclbox from %v (wrong rcpt?) via %s", sender, via)
 		}
 		metricRecvDiscoBadKey.Add(1)
@@ -1396,7 +1403,7 @@ func (c *Conn) handleDiscoMessage(msg []byte, src netip.AddrPort, derpNodeSrc ke
 	}
 
 	dm, err := disco.Parse(payload)
-	if debugDisco() {
+	if c.debugDisco() {
 		c.logf("magicsock: disco: disco.Parse = %T, %v", dm, err)
 	}
 	if err != nil {
@@ -1566,7 +1573,7 @@ func (c *Conn) handlePingLocked(dm *disco.Ping, src netip.AddrPort, di *discoInf
 		return
 	}
 
-	if !likelyHeartBeat || debugDisco() {
+	if !likelyHeartBeat || c.debugDisco() {
 		pingNodeSrcStr := dstKey.ShortString()
 		if numNodes > 1 {
 			pingNodeSrcStr = "[one-of-multi]"