From 319607625fa7485f0c7877a30db5a1b11bbeda5e Mon Sep 17 00:00:00 2001
From: Maisem Ali <maisem@tailscale.com>
Date: Thu, 5 Oct 2023 22:20:19 -0700
Subject: [PATCH] ipn/ipnlocal: fix log spam from now expected paths

These log paths were actually unexpected until the refactor in
fe95d81b43df14c7b4dcf68c764816a430206d24. This moves the logs
to the callsites where they are actually unexpected.

Fixes #9670

Signed-off-by: Maisem Ali <maisem@tailscale.com>
---
 ipn/ipnlocal/serve.go | 34 ++++++++++++++++++++++------------
 1 file changed, 22 insertions(+), 12 deletions(-)

diff --git a/ipn/ipnlocal/serve.go b/ipn/ipnlocal/serve.go
index 386e0f89e..f5c416327 100644
--- a/ipn/ipnlocal/serve.go
+++ b/ipn/ipnlocal/serve.go
@@ -160,8 +160,9 @@ func (s *serveListener) shouldWarnAboutListenError(err error) bool {
 	return true
 }
 
-// handleServeListenersAccept accepts connections for the Listener.
-// Calls incoming handler in a new goroutine for each accepted connection.
+// handleServeListenersAccept accepts connections for the Listener. It calls the
+// handler in a new goroutine for each accepted connection. This is used to
+// handle local "tailscale serve" traffic originating from the machine itself.
 func (s *serveListener) handleServeListenersAccept(ln net.Listener) error {
 	for {
 		conn, err := ln.Accept()
@@ -171,7 +172,7 @@ func (s *serveListener) handleServeListenersAccept(ln net.Listener) error {
 		srcAddr := conn.RemoteAddr().(*net.TCPAddr).AddrPort()
 		handler := s.b.tcpHandlerForServe(s.ap.Port(), srcAddr)
 		if handler == nil {
-			s.b.logf("serve RST for %v", srcAddr)
+			s.b.logf("[unexpected] local-serve: no handler for %v to port %v", srcAddr, s.ap.Port())
 			conn.Close()
 			continue
 		}
@@ -325,32 +326,43 @@ func (b *LocalBackend) DeleteForegroundSession(sessionID string) error {
 	return b.setServeConfigLocked(sc, "")
 }
 
+// HandleIngressTCPConn handles a TCP connection initiated by the ingressPeer
+// proxied to the local node over the PeerAPI.
+// Target represents the destination HostPort of the conn.
+// srcAddr represents the source AddrPort and not that of the ingressPeer.
+// getConnOrReset is a callback to get the connection, or reset if the connection
+// is no longer available.
+// sendRST is a callback to send a TCP RST to the ingressPeer indicating that
+// the connection was not accepted.
 func (b *LocalBackend) HandleIngressTCPConn(ingressPeer tailcfg.NodeView, target ipn.HostPort, srcAddr netip.AddrPort, getConnOrReset func() (net.Conn, bool), sendRST func()) {
 	b.mu.Lock()
 	sc := b.serveConfig
 	b.mu.Unlock()
 
+	// TODO(maisem,bradfitz): make this not alloc for every conn.
+	logf := logger.WithPrefix(b.logf, "handleIngress: ")
+
 	if !sc.Valid() {
-		b.logf("localbackend: got ingress conn w/o serveConfig; rejecting")
+		logf("got ingress conn w/o serveConfig; rejecting")
 		sendRST()
 		return
 	}
 
 	if !sc.HasFunnelForTarget(target) {
-		b.logf("localbackend: got ingress conn for unconfigured %q; rejecting", target)
+		logf("got ingress conn for unconfigured %q; rejecting", target)
 		sendRST()
 		return
 	}
 
 	_, port, err := net.SplitHostPort(string(target))
 	if err != nil {
-		b.logf("localbackend: got ingress conn for bad target %q; rejecting", target)
+		logf("got ingress conn for bad target %q; rejecting", target)
 		sendRST()
 		return
 	}
 	port16, err := strconv.ParseUint(port, 10, 16)
 	if err != nil {
-		b.logf("localbackend: got ingress conn for bad target %q; rejecting", target)
+		logf("got ingress conn for bad target %q; rejecting", target)
 		sendRST()
 		return
 	}
@@ -360,7 +372,7 @@ func (b *LocalBackend) HandleIngressTCPConn(ingressPeer tailcfg.NodeView, target
 		if handler != nil {
 			c, ok := getConnOrReset()
 			if !ok {
-				b.logf("localbackend: getConn didn't complete from %v to port %v", srcAddr, dport)
+				logf("getConn didn't complete from %v to port %v", srcAddr, dport)
 				return
 			}
 			handler(c)
@@ -371,12 +383,13 @@ func (b *LocalBackend) HandleIngressTCPConn(ingressPeer tailcfg.NodeView, target
 	// extend serveHTTPContext or similar.
 	handler := b.tcpHandlerForServe(dport, srcAddr)
 	if handler == nil {
+		logf("[unexpected] no matching ingress serve handler for %v to port %v", srcAddr, dport)
 		sendRST()
 		return
 	}
 	c, ok := getConnOrReset()
 	if !ok {
-		b.logf("localbackend: getConn didn't complete from %v to port %v", srcAddr, dport)
+		logf("getConn didn't complete from %v to port %v", srcAddr, dport)
 		return
 	}
 	handler(c)
@@ -390,13 +403,11 @@ func (b *LocalBackend) tcpHandlerForServe(dport uint16, srcAddr netip.AddrPort)
 	b.mu.Unlock()
 
 	if !sc.Valid() {
-		b.logf("[unexpected] localbackend: got TCP conn w/o serveConfig; from %v to port %v", srcAddr, dport)
 		return nil
 	}
 
 	tcph, ok := sc.FindTCP(dport)
 	if !ok {
-		b.logf("[unexpected] localbackend: got TCP conn without TCP config for port %v; from %v", dport, srcAddr)
 		return nil
 	}
 
@@ -468,7 +479,6 @@ func (b *LocalBackend) tcpHandlerForServe(dport uint16, srcAddr netip.AddrPort)
 		}
 	}
 
-	b.logf("closing TCP conn to port %v (from %v) with actionless TCPPortHandler", dport, srcAddr)
 	return nil
 }