From c86a610eb30ebe8402557b6c8eb04a80ce1e5ae3 Mon Sep 17 00:00:00 2001 From: Andrew Dunham Date: Mon, 21 Aug 2023 16:53:47 -0400 Subject: [PATCH] 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 Change-Id: I2c3cf6930b09717028deaff31738484cc9b008e4 --- client/tailscale/localclient.go | 47 ++++++++++++++++++++++--- cmd/tailscale/cli/debug.go | 38 +++++++++++++++----- ipn/localapi/localapi.go | 4 +++ net/portmapper/portmapper.go | 5 +++ net/portmapper/upnp.go | 62 +++++++++++++++++++++++++++++++++ 5 files changed, 142 insertions(+), 14 deletions(-) diff --git a/client/tailscale/localclient.go b/client/tailscale/localclient.go index c57b58895..9fcc8aaf2 100644 --- a/client/tailscale/localclient.go +++ b/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) diff --git a/cmd/tailscale/cli/debug.go b/cmd/tailscale/cli/debug.go index 40152ca9e..0cedc0256 100644 --- a/cmd/tailscale/cli/debug.go +++ b/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 } diff --git a/ipn/localapi/localapi.go b/ipn/localapi/localapi.go index 44ec4dc43..dcb2e60cc 100644 --- a/ipn/localapi/localapi.go +++ b/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 diff --git a/net/portmapper/portmapper.go b/net/portmapper/portmapper.go index 2e500b555..d934e202b 100644 --- a/net/portmapper/portmapper.go +++ b/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 diff --git a/net/portmapper/upnp.go b/net/portmapper/upnp.go index 34cae5840..b85eb488d 100644 --- a/net/portmapper/upnp.go +++ b/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 +}