ipnlocal,proxymap,wgengine/netstack: add optional WhoIs/proxymap debug

Updates tailscale/corp#20600

Change-Id: I2bb17af0f40603ada1ba4cecc087443e00f9392a
Co-authored-by: Maisem Ali <maisem@tailscale.com>
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>

ipn/ipnlocal/local.go

@@ -1139,6 +1139,8 @@ func (b *LocalBackend) WhoIsNodeKey(k key.NodePublic) (n tailcfg.NodeView, u tai
 	return n, u, false
 }
 
+var debugWhoIs = envknob.RegisterBool("TS_DEBUG_WHOIS")
+
 // WhoIs reports the node and user who owns the node with the given IP:port.
 // If the IP address is a Tailscale IP, the provided port may be 0.
 //
@@ -1154,6 +1156,14 @@ func (b *LocalBackend) WhoIs(proto string, ipp netip.AddrPort) (n tailcfg.NodeVi
 	b.mu.Lock()
 	defer b.mu.Unlock()
 
+	failf := func(format string, args ...any) (tailcfg.NodeView, tailcfg.UserProfile, bool) {
+		if debugWhoIs() {
+			args = append([]any{proto, ipp}, args...)
+			b.logf("whois(%q, %v) :"+format, args...)
+		}
+		return zero, u, false
+	}
+
 	nid, ok := b.nodeByAddr[ipp.Addr()]
 	if !ok {
 		var ip netip.Addr
@@ -1174,15 +1184,15 @@ func (b *LocalBackend) WhoIs(proto string, ipp netip.AddrPort) (n tailcfg.NodeVi
 			}
 		}
 		if !ok {
-			return zero, u, false
+			return failf("no IP found in ProxyMapper for %v", ipp)
 		}
 		nid, ok = b.nodeByAddr[ip]
 		if !ok {
-			return zero, u, false
+			return failf("no node for proxymapped IP %v", ip)
 		}
 	}
 	if b.netMap == nil {
-		return zero, u, false
+		return failf("no netmap")
 	}
 	n, ok = b.peers[nid]
 	if !ok {
@@ -1194,7 +1204,7 @@ func (b *LocalBackend) WhoIs(proto string, ipp netip.AddrPort) (n tailcfg.NodeVi
 	}
 	u, ok = b.netMap.UserProfiles[n.User()]
 	if !ok {
-		return zero, u, false
+		return failf("no userprofile for node %v", n.Key())
 	}
 	return n, u, true
 }

proxymap/proxymap.go

@@ -6,9 +6,13 @@
 package proxymap
 
 import (
+	"fmt"
 	"net/netip"
+	"strings"
 	"sync"
 	"time"
+
+	"tailscale.com/util/mak"
 )
 
 // Mapper tracks which localhost ip:ports correspond to which remote Tailscale
@@ -24,7 +28,26 @@ type Mapper struct {
 	// keyed first by the protocol ("tcp" or "udp"), then by the IP:port.
 	//
 	// +checklocks:mu
-	m map[string]map[netip.AddrPort]netip.Addr
+	m map[mappingKey]netip.Addr
+}
+
+// String returns a human-readable representation of the current mappings.
+func (m *Mapper) String() string {
+	m.mu.Lock()
+	defer m.mu.Unlock()
+	if len(m.m) == 0 {
+		return "no mappings"
+	}
+	var sb strings.Builder
+	for k, v := range m.m {
+		fmt.Fprintf(&sb, "%v/%v=>%v\n", k.proto, k.ap, v)
+	}
+	return sb.String()
+}
+
+type mappingKey struct {
+	proto string
+	ap    netip.AddrPort
 }
 
 // RegisterIPPortIdentity registers a given node (identified by its
@@ -36,18 +59,15 @@ type Mapper struct {
 //
 // The proto is the network protocol that is being proxied; it must be "tcp" or
 // "udp" (not e.g. "tcp4", "udp6", etc.)
-func (m *Mapper) RegisterIPPortIdentity(proto string, ipport netip.AddrPort, tsIP netip.Addr) {
+func (m *Mapper) RegisterIPPortIdentity(proto string, ipport netip.AddrPort, tsIP netip.Addr) error {
 	m.mu.Lock()
 	defer m.mu.Unlock()
-	if m.m == nil {
-		m.m = make(map[string]map[netip.AddrPort]netip.Addr)
+	k := mappingKey{proto, ipport}
+	if v, ok := m.m[k]; ok {
+		return fmt.Errorf("proxymap: RegisterIPPortIdentity: already registered: %v/%v=>%v", k.proto, k.ap, v)
 	}
-	p, ok := m.m[proto]
-	if !ok {
-		p = make(map[netip.AddrPort]netip.Addr)
-		m.m[proto] = p
-	}
-	p[ipport] = tsIP
+	mak.Set(&m.m, k, tsIP)
+	return nil
 }
 
 // UnregisterIPPortIdentity removes a temporary IP:port registration
@@ -55,8 +75,8 @@ func (m *Mapper) RegisterIPPortIdentity(proto string, ipport netip.AddrPort, tsI
 func (m *Mapper) UnregisterIPPortIdentity(proto string, ipport netip.AddrPort) {
 	m.mu.Lock()
 	defer m.mu.Unlock()
-	p := m.m[proto]
-	delete(p, ipport) // safe to delete from a nil map
+	k := mappingKey{proto, ipport}
+	delete(m.m, k) // safe to delete from a nil map
 }
 
 var whoIsSleeps = [...]time.Duration{
@@ -75,13 +95,11 @@ func (m *Mapper) WhoIsIPPort(proto string, ipport netip.AddrPort) (tsIP netip.Ad
 	// so loop a few times for now waiting for the registration
 	// to appear.
 	// TODO(bradfitz,namansood): remove this once #1616 is fixed.
+	k := mappingKey{proto, ipport}
 	for _, d := range whoIsSleeps {
 		time.Sleep(d)
 		m.mu.Lock()
-		p, ok := m.m[proto]
-		if ok {
-			tsIP, ok = p[ipport]
-		}
+		tsIP, ok := m.m[k]
 		m.mu.Unlock()
 		if ok {
 			return tsIP, true

wgengine/netstack/netstack.go

@@ -1378,12 +1378,23 @@ func (ns *Impl) forwardTCP(getClient func(...tcpip.SettableSocketOption) *gonet.
 		var stdDialer net.Dialer
 		dialFunc = stdDialer.DialContext
 	}
-	server, err := dialFunc(ctx, "tcp", dialAddrStr)
+
+	// TODO: this is racy, dialing before we register our local address. See
+	// https://github.com/tailscale/tailscale/issues/1616.
+	backend, err := dialFunc(ctx, "tcp", dialAddrStr)
 	if err != nil {
-		ns.logf("netstack: could not connect to local server at %s: %v", dialAddr.String(), err)
+		ns.logf("netstack: could not connect to local backend server at %s: %v", dialAddr.String(), err)
+		return
+	}
+	defer backend.Close()
+
+	backendLocalAddr := backend.LocalAddr().(*net.TCPAddr)
+	backendLocalIPPort := netaddr.Unmap(backendLocalAddr.AddrPort())
+	if err := ns.pm.RegisterIPPortIdentity("tcp", backendLocalIPPort, clientRemoteIP); err != nil {
+		ns.logf("netstack: could not register TCP mapping %s: %v", backendLocalIPPort, err)
 		return
 	}
-	defer server.Close()
+	defer ns.pm.UnregisterIPPortIdentity("tcp", backendLocalIPPort)
 
 	// If we get here, either the getClient call below will succeed and
 	// return something we can Close, or it will fail and will properly
@@ -1398,17 +1409,13 @@ func (ns *Impl) forwardTCP(getClient func(...tcpip.SettableSocketOption) *gonet.
 	}
 	defer client.Close()
 
-	backendLocalAddr := server.LocalAddr().(*net.TCPAddr)
-	backendLocalIPPort := netaddr.Unmap(backendLocalAddr.AddrPort())
-	ns.pm.RegisterIPPortIdentity("tcp", backendLocalIPPort, clientRemoteIP)
-	defer ns.pm.UnregisterIPPortIdentity("tcp", backendLocalIPPort)
 	connClosed := make(chan error, 2)
 	go func() {
-		_, err := io.Copy(server, client)
+		_, err := io.Copy(backend, client)
 		connClosed <- err
 	}()
 	go func() {
-		_, err := io.Copy(client, server)
+		_, err := io.Copy(client, backend)
 		connClosed <- err
 	}()
 	err = <-connClosed
@@ -1620,7 +1627,10 @@ func (ns *Impl) forwardUDP(client *gonet.UDPConn, clientAddr, dstAddr netip.Addr
 		ns.logf("could not get backend local IP:port from %v:%v", backendLocalAddr.IP, backendLocalAddr.Port)
 	}
 	if isLocal {
-		ns.pm.RegisterIPPortIdentity("udp", backendLocalIPPort, clientAddr.Addr())
+		if err := ns.pm.RegisterIPPortIdentity("udp", backendLocalIPPort, clientAddr.Addr()); err != nil {
+			ns.logf("netstack: could not register UDP mapping %s: %v", backendLocalIPPort, err)
+			return
+		}
 	}
 	ctx, cancel := context.WithCancel(context.Background())