cmd/tailscale, net/portmapper: add --log-http option to "debug portmap"

This option allows logging the raw HTTP requests and responses that the
portmapper Client makes when using UPnP. This can be extremely helpful
when debugging strange UPnP issues with users' devices, and might allow
us to avoid having to instruct users to perform a packet capture.

Updates #8992

Signed-off-by: Andrew Dunham <andrew@du.nham.ca>
Change-Id: I2c3cf6930b09717028deaff31738484cc9b008e4

client/tailscale/localclient.go

@@ -37,6 +37,7 @@ import (
 	"tailscale.com/tka"
 	"tailscale.com/types/key"
 	"tailscale.com/types/tkatype"
+	"tailscale.com/util/cmpx"
 )
 
 // defaultLocalClient is the default LocalClient when using the legacy
@@ -391,15 +392,51 @@ func (lc *LocalClient) DebugAction(ctx context.Context, action string) error {
 	return nil
 }
 
+// DebugPortmapOpts contains options for the DebugPortmap command.
+type DebugPortmapOpts struct {
+	// Duration is how long the mapping should be created for. It defaults
+	// to 5 seconds if not set.
+	Duration time.Duration
+
+	// Type is the kind of portmap to debug. The empty string instructs the
+	// portmap client to perform all known types. Other valid options are
+	// "pmp", "pcp", and "upnp".
+	Type string
+
+	// GatewayAddr specifies the gateway address used during portmapping.
+	// If set, SelfAddr must also be set. If unset, it will be
+	// autodetected.
+	GatewayAddr netip.Addr
+
+	// SelfAddr specifies the gateway address used during portmapping. If
+	// set, GatewayAddr must also be set. If unset, it will be
+	// autodetected.
+	SelfAddr netip.Addr
+
+	// LogHTTP instructs the debug-portmap endpoint to print all HTTP
+	// requests and responses made to the logs.
+	LogHTTP bool
+}
+
 // DebugPortmap invokes the debug-portmap endpoint, and returns an
 // io.ReadCloser that can be used to read the logs that are printed during this
 // process.
-func (lc *LocalClient) DebugPortmap(ctx context.Context, duration time.Duration, ty, gwSelf string) (io.ReadCloser, error) {
+//
+// opts can be nil; if so, default values will be used.
+func (lc *LocalClient) DebugPortmap(ctx context.Context, opts *DebugPortmapOpts) (io.ReadCloser, error) {
 	vals := make(url.Values)
-	vals.Set("duration", duration.String())
-	vals.Set("type", ty)
-	if gwSelf != "" {
-		vals.Set("gateway_and_self", gwSelf)
+	if opts == nil {
+		opts = &DebugPortmapOpts{}
+	}
+
+	vals.Set("duration", cmpx.Or(opts.Duration, 5*time.Second).String())
+	vals.Set("type", opts.Type)
+	vals.Set("log_http", strconv.FormatBool(opts.LogHTTP))
+
+	if opts.GatewayAddr.IsValid() != opts.SelfAddr.IsValid() {
+		return nil, fmt.Errorf("both GatewayAddr and SelfAddr must be provided if one is")
+	} else if opts.GatewayAddr.IsValid() {
+		vals.Set("gateway_and_self", fmt.Sprintf("%s/%s", opts.GatewayAddr, opts.SelfAddr))
 	}
 
 	req, err := http.NewRequestWithContext(ctx, "GET", "http://"+apitype.LocalAPIHost+"/localapi/v0/debug-portmap?"+vals.Encode(), nil)

cmd/tailscale/cli/debug.go

@@ -28,6 +28,7 @@ import (
 
 	"github.com/peterbourgon/ff/v3/ffcli"
 	"golang.org/x/net/http/httpproxy"
+	"tailscale.com/client/tailscale"
 	"tailscale.com/client/tailscale/apitype"
 	"tailscale.com/control/controlhttp"
 	"tailscale.com/hostinfo"
@@ -219,7 +220,9 @@ var debugCmd = &ffcli.Command{
 				fs := newFlagSet("portmap")
 				fs.DurationVar(&debugPortmapArgs.duration, "duration", 5*time.Second, "timeout for port mapping")
 				fs.StringVar(&debugPortmapArgs.ty, "type", "", `portmap debug type (one of "", "pmp", "pcp", or "upnp")`)
-				fs.StringVar(&debugPortmapArgs.gwSelf, "gw-self", "", `override gateway and self IP (format: "gatewayIP/selfIP")`)
+				fs.StringVar(&debugPortmapArgs.gatewayAddr, "gateway-addr", "", `override gateway IP (must also pass --self-addr)`)
+				fs.StringVar(&debugPortmapArgs.selfAddr, "self-addr", "", `override self IP (must also pass --gateway-addr)`)
+				fs.BoolVar(&debugPortmapArgs.logHTTP, "log-http", false, `print all HTTP requests and responses to the log`)
 				return fs
 			})(),
 		},
@@ -818,17 +821,34 @@ func runCapture(ctx context.Context, args []string) error {
 }
 
 var debugPortmapArgs struct {
-	duration time.Duration
-	gwSelf   string
-	ty       string
+	duration    time.Duration
+	gatewayAddr string
+	selfAddr    string
+	ty          string
+	logHTTP     bool
 }
 
 func debugPortmap(ctx context.Context, args []string) error {
-	rc, err := localClient.DebugPortmap(ctx,
-		debugPortmapArgs.duration,
-		debugPortmapArgs.ty,
-		debugPortmapArgs.gwSelf,
-	)
+	opts := &tailscale.DebugPortmapOpts{
+		Duration: debugPortmapArgs.duration,
+		Type:     debugPortmapArgs.ty,
+		LogHTTP:  debugPortmapArgs.logHTTP,
+	}
+	if (debugPortmapArgs.gatewayAddr != "") != (debugPortmapArgs.selfAddr != "") {
+		return fmt.Errorf("if one of --gateway-addr and --self-addr is provided, the other must be as well")
+	}
+	if debugPortmapArgs.gatewayAddr != "" {
+		var err error
+		opts.GatewayAddr, err = netip.ParseAddr(debugPortmapArgs.gatewayAddr)
+		if err != nil {
+			return fmt.Errorf("invalid --gateway-addr: %w", err)
+		}
+		opts.SelfAddr, err = netip.ParseAddr(debugPortmapArgs.selfAddr)
+		if err != nil {
+			return fmt.Errorf("invalid --self-addr: %w", err)
+		}
+	}
+	rc, err := localClient.DebugPortmap(ctx, opts)
 	if err != nil {
 		return err
 	}

ipn/localapi/localapi.go

@@ -660,6 +660,10 @@ func (h *Handler) serveDebugPortmap(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	if defBool(r.FormValue("log_http"), false) {
+		debugKnobs.LogHTTP = true
+	}
+
 	var (
 		logLock     sync.Mutex
 		handlerDone bool

net/portmapper/portmapper.go

@@ -36,6 +36,11 @@ type DebugKnobs struct {
 	// to its logger.
 	VerboseLogs bool
 
+	// LogHTTP tells the Client to print the raw HTTP logs (from UPnP) to
+	// its logger. This is useful when debugging buggy UPnP
+	// implementations.
+	LogHTTP bool
+
 	// Disable* disables a specific service from mapping.
 	DisableUPnP bool
 	DisablePMP  bool

net/portmapper/upnp.go

@@ -12,12 +12,14 @@ import (
 	"bytes"
 	"context"
 	"fmt"
+	"io"
 	"math/rand"
 	"net"
 	"net/http"
 	"net/netip"
 	"net/url"
 	"strings"
+	"sync/atomic"
 	"time"
 
 	"github.com/tailscale/goupnp"
@@ -261,6 +263,9 @@ func (c *Client) upnpHTTPClientLocked() *http.Client {
 				IdleConnTimeout: 2 * time.Second, // LAN is cheap
 			},
 		}
+		if c.debug.LogHTTP {
+			c.uPnPHTTPClient = requestLogger(c.logf, c.uPnPHTTPClient)
+		}
 	}
 	return c.uPnPHTTPClient
 }
@@ -369,3 +374,60 @@ func parseUPnPDiscoResponse(body []byte) (uPnPDiscoResponse, error) {
 	r.USN = res.Header.Get("Usn")
 	return r, nil
 }
+
+type roundTripperFunc func(*http.Request) (*http.Response, error)
+
+func (r roundTripperFunc) RoundTrip(req *http.Request) (*http.Response, error) {
+	return r(req)
+}
+
+func requestLogger(logf logger.Logf, client *http.Client) *http.Client {
+	// Clone the HTTP client, and override the Transport to log to the
+	// provided logger.
+	ret := *client
+	oldTransport := ret.Transport
+
+	var requestCounter atomic.Uint64
+	loggingTransport := roundTripperFunc(func(req *http.Request) (*http.Response, error) {
+		ctr := requestCounter.Add(1)
+
+		// Read the body and re-set it.
+		var (
+			body []byte
+			err  error
+		)
+		if req.Body != nil {
+			body, err = io.ReadAll(req.Body)
+			req.Body.Close()
+			if err != nil {
+				return nil, err
+			}
+			req.Body = io.NopCloser(bytes.NewReader(body))
+		}
+
+		logf("request[%d]: %s %q body=%q", ctr, req.Method, req.URL, body)
+
+		resp, err := oldTransport.RoundTrip(req)
+		if err != nil {
+			logf("response[%d]: err=%v", err)
+			return nil, err
+		}
+
+		// Read the response body
+		if resp.Body != nil {
+			body, err = io.ReadAll(resp.Body)
+			resp.Body.Close()
+			if err != nil {
+				logf("response[%d]: %d bodyErr=%v", resp.StatusCode, err)
+				return nil, err
+			}
+			resp.Body = io.NopCloser(bytes.NewReader(body))
+		}
+
+		logf("response[%d]: %d body=%q", ctr, resp.StatusCode, body)
+		return resp, nil
+	})
+	ret.Transport = loggingTransport
+
+	return &ret
+}