vnet: reduce some log spam

Updates #13038

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

cmd/tta/tta.go

@@ -141,7 +141,6 @@ func main() {
 	for {
 		<-needConnCh
 		c, err := connect()
-		log.Printf("Connect: %v", err)
 		if err != nil {
 			s := err.Error()
 			if s != lastErr {

tstest/integration/nat/nat_test.go

@@ -7,6 +7,7 @@ import (
 	"context"
 	"encoding/json"
 	"errors"
+	"flag"
 	"fmt"
 	"io"
 	"log"
@@ -27,9 +28,10 @@ import (
 	"tailscale.com/ipn/ipnstate"
 	"tailscale.com/tailcfg"
 	"tailscale.com/tstest/natlab/vnet"
-	"tailscale.com/types/logger"
 )
 
+var logTailscaled = flag.Bool("log-tailscaled", false, "log tailscaled output")
+
 type natTest struct {
 	tb      testing.TB
 	base    string // base image
@@ -94,6 +96,13 @@ func easy(c *vnet.Config) *vnet.Node {
 		fmt.Sprintf("192.168.%d.1/24", n), vnet.EasyNAT))
 }
 
+func one2one(c *vnet.Config) *vnet.Node {
+	n := c.NumNodes() + 1
+	return c.AddNode(c.AddNetwork(
+		fmt.Sprintf("2.%d.%d.%d", n, n, n), // public IP
+		fmt.Sprintf("172.16.%d.1/24", n), vnet.One2OneNAT))
+}
+
 func easyPMP(c *vnet.Config) *vnet.Node {
 	n := c.NumNodes() + 1
 	return c.AddNode(c.AddNetwork(
@@ -205,11 +214,13 @@ func (nt *natTest) runTest(node1, node2 addNodeFunc) {
 	for i, c := range clients {
 		i, c := i, c
 		eg.Go(func() error {
+			if *logTailscaled {
 				wg.Add(1)
 				go func() {
 					defer wg.Done()
 					streamDaemonLogs(ctx, t, c, fmt.Sprintf("node%d:", i))
 				}()
+			}
 			st, err := c.Status(ctx)
 			if err != nil {
 				return fmt.Errorf("node%d status: %w", i, err)
@@ -236,10 +247,41 @@ func (nt *natTest) runTest(node1, node2 addNodeFunc) {
 		t.Fatalf("initial setup: %v", err)
 	}
 
-	route, err := ping(ctx, lc1, sts[1].Self.TailscaleIPs[0])
-	t.Logf("ping route: %v, %v", logger.AsJSON(route), err)
+	defer nt.vnet.Close()
+
+	pingRes, err := ping(ctx, lc1, sts[1].Self.TailscaleIPs[0])
+	if err != nil {
+		t.Fatalf("ping failure: %v", err)
+	}
+	route := classifyPing(pingRes)
+	t.Logf("ping route: %v", route)
+}
+
+func classifyPing(pr *ipnstate.PingResult) pingRoute {
+	if pr == nil {
+		return routeNil
+	}
+	if pr.Endpoint != "" {
+		ap, err := netip.ParseAddrPort(pr.Endpoint)
+		if err == nil {
+			if ap.Addr().IsPrivate() {
+				return routeLocal
+			}
+			return routeDirect
+		}
+	}
+	return routeDERP // presumably
 }
 
+type pingRoute string
+
+const (
+	routeDERP   pingRoute = "derp"
+	routeLocal  pingRoute = "local"
+	routeDirect pingRoute = "direct"
+	routeNil    pingRoute = "nil" // *ipnstate.PingResult is nil
+)
+
 func streamDaemonLogs(ctx context.Context, t testing.TB, c *vnet.NodeAgentClient, nodeID string) {
 	ctx, cancel := context.WithCancel(ctx)
 	defer cancel()
@@ -336,3 +378,23 @@ func TestEasyPMPHard(t *testing.T) {
 	nt := newNatTest(t)
 	nt.runTest(easyPMP, hard)
 }
+
+func TestHardHardPMP(t *testing.T) {
+	nt := newNatTest(t)
+	nt.runTest(hard, hardPMP)
+}
+
+func TestHardHard(t *testing.T) {
+	nt := newNatTest(t)
+	nt.runTest(hard, hard)
+}
+
+func TestEasyOne2One(t *testing.T) {
+	nt := newNatTest(t)
+	nt.runTest(easy, one2one)
+}
+
+func TestHardOne2One(t *testing.T) {
+	nt := newNatTest(t)
+	nt.runTest(hard, one2one)
+}

tstest/natlab/vnet/vnet.go

@@ -247,7 +247,6 @@ func stringifyTEI(tei stack.TransportEndpointID) string {
 func (n *network) acceptTCP(r *tcp.ForwarderRequest) {
 	reqDetails := r.ID()
 
-	log.Printf("AcceptTCP: %v", stringifyTEI(reqDetails))
 	clientRemoteIP := netaddrIPFromNetstackIP(reqDetails.RemoteAddress)
 	destIP := netaddrIPFromNetstackIP(reqDetails.LocalAddress)
 	destPort := reqDetails.LocalPort
@@ -325,6 +324,8 @@ func (n *network) acceptTCP(r *tcp.ForwarderRequest) {
 		return
 	}
 
+	log.Printf("vnet-AcceptTCP: %v", stringifyTEI(reqDetails))
+
 	var targetDial string
 	if n.s.derpIPs.Contains(destIP) {
 		targetDial = destIP.String() + ":" + strconv.Itoa(int(destPort))
@@ -641,12 +642,20 @@ func (s *Server) ServeUnixConn(uc *net.UnixConn, proto Protocol) {
 			packetRaw = buf[:n]
 		} else if proto == ProtocolQEMU {
 			if _, err := io.ReadFull(uc, buf[:4]); err != nil {
+				if s.shutdownCtx.Err() != nil {
+					// Return without logging.
+					return
+				}
 				log.Printf("ReadFull header: %v", err)
 				return
 			}
 			n := binary.BigEndian.Uint32(buf[:4])
 
 			if _, err := io.ReadFull(uc, buf[4:4+n]); err != nil {
+				if s.shutdownCtx.Err() != nil {
+					// Return without logging.
+					return
+				}
 				log.Printf("ReadFull pkt: %v", err)
 				return
 			}
@@ -1234,16 +1243,13 @@ func (n *network) doNATIn(src, dst netip.AddrPort) (newDst netip.AddrPort) {
 				peerWAN: src,
 				lanAP:   lanAP.dst,
 			}, dst)
-			n.logf("XXX NAT: doNatIn: port mapping %v=>%v", dst, lanAP.dst)
+			//n.logf("NAT: doNatIn: port mapping %v=>%v", dst, lanAP.dst)
 			return lanAP.dst
 		}
-		n.logf("XXX NAT: doNatIn: port mapping EXPIRED for %v=>%v", dst, lanAP.dst)
+		n.logf("NAT: doNatIn: port mapping EXPIRED for %v=>%v", dst, lanAP.dst)
 		delete(n.portMap, dst)
 		return netip.AddrPort{}
 	}
-	if len(n.portMap) > 0 {
-		n.logf("XXX NAT: doNatIn: no port mapping for %v; have %v", dst, n.portMap)
-	}
 
 	return n.natTable.PickIncomingDst(src, dst, now)
 }
@@ -1293,7 +1299,7 @@ func (n *network) doPortMap(src netip.Addr, dstLANPort, wantExtPort uint16, sec
 				dst:    dst,
 				expiry: time.Now().Add(time.Duration(sec) * time.Second),
 			})
-			n.logf("XXX allocated NAT mapping from %v to %v", wanAP, dst)
+			n.logf("vnet: allocated NAT mapping from %v to %v", wanAP, dst)
 			return wanAP.Port(), true
 		}
 		wantExtPort = rand.N(uint16(32<<10)) + 32<<10