From edb02b63f89bbc7256e5202783e9bb44134500f8 Mon Sep 17 00:00:00 2001 From: Mihai Parparita Date: Wed, 12 Apr 2023 18:23:22 -0700 Subject: [PATCH] net/sockstats: pass in logger to sockstats.WithSockStats Using log.Printf may end up being printed out to the console, which is not desirable. I noticed this when I was investigating some client logs with `sockstats: trace "NetcheckClient" was overwritten by another`. That turns to be harmless/expected (the netcheck client will fall back to the DERP client in some cases, which does its own sockstats trace). However, the log output could be visible to users if running the `tailscale netcheck` CLI command, which would be needlessly confusing. Updates tailscale/corp#9230 Signed-off-by: Mihai Parparita --- control/controlclient/auto.go | 8 ++++---- control/controlhttp/client.go | 2 +- derp/derphttp/derphttp_client.go | 2 +- logtail/logtail.go | 2 +- net/dns/resolver/forwarder.go | 4 ++-- net/netcheck/netcheck.go | 2 +- net/portmapper/portmapper.go | 2 +- net/sockstats/sockstats.go | 5 +++-- net/sockstats/sockstats_noop.go | 4 +++- net/sockstats/sockstats_tsgo.go | 6 +++--- wgengine/magicsock/magicsock.go | 4 ++-- 11 files changed, 22 insertions(+), 19 deletions(-) diff --git a/control/controlclient/auto.go b/control/controlclient/auto.go index ddd0d4f2b..dab37a510 100644 --- a/control/controlclient/auto.go +++ b/control/controlclient/auto.go @@ -121,10 +121,10 @@ func NewNoStart(opts Options) (_ *Auto, err error) { statusFunc: opts.Status, } c.authCtx, c.authCancel = context.WithCancel(context.Background()) - c.authCtx = sockstats.WithSockStats(c.authCtx, sockstats.LabelControlClientAuto) + c.authCtx = sockstats.WithSockStats(c.authCtx, sockstats.LabelControlClientAuto, opts.Logf) c.mapCtx, c.mapCancel = context.WithCancel(context.Background()) - c.mapCtx = sockstats.WithSockStats(c.mapCtx, sockstats.LabelControlClientAuto) + c.mapCtx = sockstats.WithSockStats(c.mapCtx, sockstats.LabelControlClientAuto, opts.Logf) c.unregisterHealthWatch = health.RegisterWatcher(direct.ReportHealthChange) return c, nil @@ -244,7 +244,7 @@ func (c *Auto) cancelAuth() { } if !c.closed { c.authCtx, c.authCancel = context.WithCancel(context.Background()) - c.authCtx = sockstats.WithSockStats(c.authCtx, sockstats.LabelControlClientAuto) + c.authCtx = sockstats.WithSockStats(c.authCtx, sockstats.LabelControlClientAuto, c.logf) } c.mu.Unlock() } @@ -255,7 +255,7 @@ func (c *Auto) cancelMapLocked() { } if !c.closed { c.mapCtx, c.mapCancel = context.WithCancel(context.Background()) - c.mapCtx = sockstats.WithSockStats(c.mapCtx, sockstats.LabelControlClientAuto) + c.mapCtx = sockstats.WithSockStats(c.mapCtx, sockstats.LabelControlClientAuto, c.logf) } } diff --git a/control/controlhttp/client.go b/control/controlhttp/client.go index d6fd9a8c5..79eb43ae8 100644 --- a/control/controlhttp/client.go +++ b/control/controlhttp/client.go @@ -273,7 +273,7 @@ func (a *Dialer) dialHost(ctx context.Context, addr netip.Addr) (*ClientConn, er ctx, cancel := context.WithCancel(ctx) defer cancel() - ctx = sockstats.WithSockStats(ctx, sockstats.LabelControlClientDialer) + ctx = sockstats.WithSockStats(ctx, sockstats.LabelControlClientDialer, a.logf) // u80 and u443 are the URLs we'll try to hit over HTTP or HTTPS, // respectively, in order to do the HTTP upgrade to a net.Conn over which diff --git a/derp/derphttp/derphttp_client.go b/derp/derphttp/derphttp_client.go index edd45ee99..349838dfa 100644 --- a/derp/derphttp/derphttp_client.go +++ b/derp/derphttp/derphttp_client.go @@ -632,7 +632,7 @@ func (c *Client) dialNode(ctx context.Context, n *tailcfg.DERPNode) (net.Conn, e ctx, cancel := context.WithTimeout(ctx, dialNodeTimeout) defer cancel() - ctx = sockstats.WithSockStats(ctx, sockstats.LabelDERPHTTPClient) + ctx = sockstats.WithSockStats(ctx, sockstats.LabelDERPHTTPClient, c.logf) nwait := 0 startDial := func(dstPrimary, proto string) { diff --git a/logtail/logtail.go b/logtail/logtail.go index 33f9754e2..92e544fed 100644 --- a/logtail/logtail.go +++ b/logtail/logtail.go @@ -435,7 +435,7 @@ func (l *Logger) awaitInternetUp(ctx context.Context) { // origlen of -1 indicates that the body is not compressed. func (l *Logger) upload(ctx context.Context, body []byte, origlen int) (uploaded bool, err error) { const maxUploadTime = 45 * time.Second - ctx = sockstats.WithSockStats(ctx, l.sockstatsLabel) + ctx = sockstats.WithSockStats(ctx, l.sockstatsLabel, l.Logf) ctx, cancel := context.WithTimeout(ctx, maxUploadTime) defer cancel() diff --git a/net/dns/resolver/forwarder.go b/net/dns/resolver/forwarder.go index 3619bac8c..2ed38f710 100644 --- a/net/dns/resolver/forwarder.go +++ b/net/dns/resolver/forwarder.go @@ -408,7 +408,7 @@ func (f *forwarder) getKnownDoHClientForProvider(urlBase string) (c *http.Client const dohType = "application/dns-message" func (f *forwarder) sendDoH(ctx context.Context, urlBase string, c *http.Client, packet []byte) ([]byte, error) { - ctx = sockstats.WithSockStats(ctx, sockstats.LabelDNSForwarderDoH) + ctx = sockstats.WithSockStats(ctx, sockstats.LabelDNSForwarderDoH, f.logf) metricDNSFwdDoH.Add(1) req, err := http.NewRequestWithContext(ctx, "POST", urlBase, bytes.NewReader(packet)) if err != nil { @@ -488,7 +488,7 @@ func (f *forwarder) sendUDP(ctx context.Context, fq *forwardQuery, rr resolverAn return nil, fmt.Errorf("unrecognized resolver type %q", rr.name.Addr) } metricDNSFwdUDP.Add(1) - ctx = sockstats.WithSockStats(ctx, sockstats.LabelDNSForwarderUDP) + ctx = sockstats.WithSockStats(ctx, sockstats.LabelDNSForwarderUDP, f.logf) ln, err := f.packetListener(ipp.Addr()) if err != nil { diff --git a/net/netcheck/netcheck.go b/net/netcheck/netcheck.go index d53eb7ee2..b941340f1 100644 --- a/net/netcheck/netcheck.go +++ b/net/netcheck/netcheck.go @@ -787,7 +787,7 @@ func (c *Client) GetReport(ctx context.Context, dm *tailcfg.DERPMap) (_ *Report, ctx, cancel := context.WithTimeout(ctx, overallProbeTimeout) defer cancel() - ctx = sockstats.WithSockStats(ctx, sockstats.LabelNetcheckClient) + ctx = sockstats.WithSockStats(ctx, sockstats.LabelNetcheckClient, c.logf) if dm == nil { return nil, errors.New("netcheck: GetReport: DERP map is nil") diff --git a/net/portmapper/portmapper.go b/net/portmapper/portmapper.go index 187868356..6005632dd 100644 --- a/net/portmapper/portmapper.go +++ b/net/portmapper/portmapper.go @@ -249,7 +249,7 @@ func (c *Client) upnpPort() uint16 { } func (c *Client) listenPacket(ctx context.Context, network, addr string) (nettype.PacketConn, error) { - ctx = sockstats.WithSockStats(ctx, sockstats.LabelPortmapperClient) + ctx = sockstats.WithSockStats(ctx, sockstats.LabelPortmapperClient, c.logf) // When running under testing conditions, we bind the IGD server // to localhost, and may be running in an environment where our diff --git a/net/sockstats/sockstats.go b/net/sockstats/sockstats.go index 050844d3b..97aa0236c 100644 --- a/net/sockstats/sockstats.go +++ b/net/sockstats/sockstats.go @@ -12,6 +12,7 @@ import ( "context" "tailscale.com/net/interfaces" + "tailscale.com/types/logger" ) // SockStats contains statistics for sockets instrumented with the @@ -54,8 +55,8 @@ const ( // WithSockStats instruments a context so that sockets created with it will // have their statistics collected. -func WithSockStats(ctx context.Context, label Label) context.Context { - return withSockStats(ctx, label) +func WithSockStats(ctx context.Context, label Label, logf logger.Logf) context.Context { + return withSockStats(ctx, label, logf) } // Get returns the current socket statistics. diff --git a/net/sockstats/sockstats_noop.go b/net/sockstats/sockstats_noop.go index 1de51e9ae..c988249b8 100644 --- a/net/sockstats/sockstats_noop.go +++ b/net/sockstats/sockstats_noop.go @@ -7,11 +7,13 @@ package sockstats import ( "context" + + "tailscale.com/types/logger" ) const IsAvailable = false -func withSockStats(ctx context.Context, label Label) context.Context { +func withSockStats(ctx context.Context, label Label, logf logger.Logf) context.Context { return ctx } diff --git a/net/sockstats/sockstats_tsgo.go b/net/sockstats/sockstats_tsgo.go index 05b6dc5a1..c243b8161 100644 --- a/net/sockstats/sockstats_tsgo.go +++ b/net/sockstats/sockstats_tsgo.go @@ -8,7 +8,6 @@ package sockstats import ( "context" "fmt" - "log" "math" "net" "strings" @@ -18,6 +17,7 @@ import ( "time" "tailscale.com/net/interfaces" + "tailscale.com/types/logger" "tailscale.com/util/clientmetric" ) @@ -71,7 +71,7 @@ func init() { sockStats.radioHighMetric.DisableDeltas() } -func withSockStats(ctx context.Context, label Label) context.Context { +func withSockStats(ctx context.Context, label Label, logf logger.Logf) context.Context { sockStats.mu.Lock() defer sockStats.mu.Unlock() counters, ok := sockStats.countersByLabel[label] @@ -157,7 +157,7 @@ func withSockStats(ctx context.Context, label Label) context.Context { } } willOverwrite := func(trace *net.SockTrace) { - log.Printf("sockstats: trace %q was overwritten by another", label) + logf("sockstats: trace %q was overwritten by another", label) } return net.WithSockTrace(ctx, &net.SockTrace{ diff --git a/wgengine/magicsock/magicsock.go b/wgengine/magicsock/magicsock.go index b79f9de03..c4511b33f 100644 --- a/wgengine/magicsock/magicsock.go +++ b/wgengine/magicsock/magicsock.go @@ -3226,9 +3226,9 @@ func (c *Conn) ReSTUN(why string) { func (c *Conn) listenPacket(network string, port uint16) (nettype.PacketConn, error) { ctx := context.Background() // unused without DNS name to resolve if network == "udp4" { - ctx = sockstats.WithSockStats(ctx, sockstats.LabelMagicsockConnUDP4) + ctx = sockstats.WithSockStats(ctx, sockstats.LabelMagicsockConnUDP4, c.logf) } else { - ctx = sockstats.WithSockStats(ctx, sockstats.LabelMagicsockConnUDP6) + ctx = sockstats.WithSockStats(ctx, sockstats.LabelMagicsockConnUDP6, c.logf) } addr := net.JoinHostPort("", fmt.Sprint(port)) if c.testOnlyPacketListener != nil {