From 73249f8032c3553a914785f0c76294807a0d4bd3 Mon Sep 17 00:00:00 2001 From: Brad Fitzpatrick Date: Thu, 9 Apr 2020 13:13:05 -0700 Subject: [PATCH] netcheck: aggregate spammy logging onto one concise line --- cmd/tailscale/netcheck.go | 3 ++- go.sum | 46 +++++++++++++++++++++++++++++++++++++++ netcheck/netcheck.go | 43 +++++++++++++++++++++++++++++++++--- 3 files changed, 88 insertions(+), 4 deletions(-) diff --git a/cmd/tailscale/netcheck.go b/cmd/tailscale/netcheck.go index 2ee1c23ca..00cd4bed6 100644 --- a/cmd/tailscale/netcheck.go +++ b/cmd/tailscale/netcheck.go @@ -14,6 +14,7 @@ import ( "tailscale.com/derp/derpmap" "tailscale.com/net/dnscache" "tailscale.com/netcheck" + "tailscale.com/types/logger" ) var netcheckCmd = &ffcli.Command{ @@ -26,7 +27,7 @@ var netcheckCmd = &ffcli.Command{ func runNetcheck(ctx context.Context, args []string) error { c := &netcheck.Client{ DERP: derpmap.Prod(), - Logf: log.Printf, + Logf: logger.WithPrefix(log.Printf, "netcheck: "), DNSCache: dnscache.Get(), } diff --git a/go.sum b/go.sum index dc05b156c..950558c4a 100644 --- a/go.sum +++ b/go.sum @@ -135,6 +135,52 @@ github.com/stretchr/testify v1.4.0 h1:2E4SXV/wtOkTonXsotYi4li6zVWxYlZuYNCXe9XRJy github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= github.com/tailscale/winipcfg-go v0.0.0-20200213045944-185b07f8233f h1:q2ynfOHxHaaMnkZ1YHswWeO6wEk7IyOnkFozytZ1ztc= github.com/tailscale/winipcfg-go v0.0.0-20200213045944-185b07f8233f/go.mod h1:x880GWw5fvrl2DVTQ04ttXQD4DuppTt1Yz6wLibbjNE= +github.com/tailscale/wireguard-go v0.0.0-20191108062213-b93cdd0582db h1:oP0crfwOb3WZSVrMVm/o51NXN2JirDlcdlNEIPTmgI0= +github.com/tailscale/wireguard-go v0.0.0-20200207221558-a158079b156a h1:5TWA3nl2QUfL9OiE3tlBpqJd4GYd4hbGtDNkWQQ2fyc= +github.com/tailscale/wireguard-go v0.0.0-20200207221558-a158079b156a/go.mod h1:QPS8HjBzzAXoQNndUNx2efJaQbCCz8nI2Cv1ksTUHyY= +github.com/tailscale/wireguard-go v0.0.0-20200208161837-3cd0a483944a h1:vIyObUBvnXB1XTKTBM4AgoUFR9RHiz/kslGHClkXQVg= +github.com/tailscale/wireguard-go v0.0.0-20200208161837-3cd0a483944a/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200208214841-2981baf46731 h1:sNmny/5pHqHdm081Fx8rcNFnwt0zTGuee/0+Jz+tXCA= +github.com/tailscale/wireguard-go v0.0.0-20200208214841-2981baf46731/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200211020303-f39bc8eeee1b h1:99LOgoPy0PcmT+yg1HiPJXk/aV/KWeGGh4WtSVB7noM= +github.com/tailscale/wireguard-go v0.0.0-20200211020303-f39bc8eeee1b/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200213180345-a7c4b7719b1d h1:LVJovgZxbmPxtY6kJm4vwMtk0HpcNeI+vU2jB3T8M40= +github.com/tailscale/wireguard-go v0.0.0-20200213180345-a7c4b7719b1d/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200219153015-ff5ce9e55c86 h1:yVWApjTol2CR3dVbiiSOI78KnElu3AlHFvntYM2egBU= +github.com/tailscale/wireguard-go v0.0.0-20200219153015-ff5ce9e55c86/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200224122332-ad79bbddc844 h1:CChfZok8JbY2dT+BNLHAcCLcGuCTBEhrkYtUwOk5rVY= +github.com/tailscale/wireguard-go v0.0.0-20200224122332-ad79bbddc844/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200225215529-3ec48fad1002 h1:F/IqMilbeud18Ef4kU5oAFDgjD9tgl7pq3OFcqoCEKM= +github.com/tailscale/wireguard-go v0.0.0-20200225215529-3ec48fad1002/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200228112021-e513af474d50 h1:A3jG81hD8NVUdzrIus7RfGnZy8i47xHQW4CXjQFnnCY= +github.com/tailscale/wireguard-go v0.0.0-20200228112021-e513af474d50/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200228184309-3f8d44fb81cd h1:d+WIJL0sRFBqxOjLlUD3exOV68oEVqndTvAzjAZpGNA= +github.com/tailscale/wireguard-go v0.0.0-20200228184309-3f8d44fb81cd/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200301084640-52819259e449 h1:MySSF619UHACu0gIDUq032SlZXGTl3M6S2zSl3A2gt8= +github.com/tailscale/wireguard-go v0.0.0-20200301084640-52819259e449/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200301090855-c9a152bc3b51 h1:9U7gdTXXgX7zoPAShuOnh9KTi3nInbkihuTGcNpuCow= +github.com/tailscale/wireguard-go v0.0.0-20200301090855-c9a152bc3b51/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200301220325-351e6067e97c h1:Fxmm2RUWZEC6H1a+9CoKm0vjvwr4VUv9H930PBRNh6s= +github.com/tailscale/wireguard-go v0.0.0-20200301220325-351e6067e97c/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200305022019-7888c7edfed2 h1:qjA3efFS6+yVTOqZAeXq6lY9A0oUn6zp+zWYb/alfCA= +github.com/tailscale/wireguard-go v0.0.0-20200305022019-7888c7edfed2/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200307073332-1d43cf6b424f h1:rojkwH6Re+VTvBv1rmmT80Lj6+hUFUDLGsN153Jh4XE= +github.com/tailscale/wireguard-go v0.0.0-20200307073332-1d43cf6b424f/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200311005428-826dfc85c223/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200311172358-e98fb01bbec2 h1:Bwz1G3mEdi9AMRKn/TJIOX+NbUWLssas8QVMb+s6APg= +github.com/tailscale/wireguard-go v0.0.0-20200311172358-e98fb01bbec2/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200317013323-239518935266 h1:Dhtc6KmHWCBWukI47jywK+9vIxFQxFIL5qxSIgg7QdQ= +github.com/tailscale/wireguard-go v0.0.0-20200317013323-239518935266/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200317153427-3c84b2e08219 h1:BMAPRagODduo1pqKYbE4i0ISAqx2h8IlQ77WxWIipl8= +github.com/tailscale/wireguard-go v0.0.0-20200317153427-3c84b2e08219/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200318202300-fc0d3b3791f3 h1:zmTJDnwxACJTQaQ6xOvbxaX5z1FUspUYchN+Z+gPIRo= +github.com/tailscale/wireguard-go v0.0.0-20200318202300-fc0d3b3791f3/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200318220557-3a43a6493fd7 h1:+j4H4XjC373rxZZTQz8fRu/c4m9jGEWTiaKYdWeB2w4= +github.com/tailscale/wireguard-go v0.0.0-20200318220557-3a43a6493fd7/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200320054525-e913b7c8517d h1:5Hc2ERvHL13UZ09+CliMAnHLcHmWb6UQbFqtXpn9Dhs= +github.com/tailscale/wireguard-go v0.0.0-20200320054525-e913b7c8517d/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= +github.com/tailscale/wireguard-go v0.0.0-20200325185614-bd634ffe2ded h1:h5xaqGuzy578xFcIpbBIP1vWeFwggf5RC8PFBEldHr4= +github.com/tailscale/wireguard-go v0.0.0-20200325185614-bd634ffe2ded/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= github.com/tailscale/wireguard-go v0.0.0-20200407164751-7f0c43dd1145 h1:n/ErEski7q1+ew00eaoiCmyx/5Wtf9nKBhWYLsmID/U= github.com/tailscale/wireguard-go v0.0.0-20200407164751-7f0c43dd1145/go.mod h1:JPm5cTfu1K+qDFRbiHy0sOlHUylYQbpl356sdYFD8V4= github.com/toqueteos/webbrowser v1.2.0 h1:tVP/gpK69Fx+qMJKsLE7TD8LuGWPnEV71wBN9rrstGQ= diff --git a/netcheck/netcheck.go b/netcheck/netcheck.go index e7795d7ae..5338c2d8c 100644 --- a/netcheck/netcheck.go +++ b/netcheck/netcheck.go @@ -6,6 +6,7 @@ package netcheck import ( + "bytes" "context" "errors" "fmt" @@ -236,8 +237,6 @@ func (c *Client) GetReport(ctx context.Context) (*Report, error) { return gotEP4 != "" } add := func(server, ipPort string, d time.Duration) { - c.logf("%s says we are %s (in %v)", server, ipPort, d.Round(time.Millisecond)) - ua, err := net.ResolveUDPAddr("udp", ipPort) if err != nil { c.logf("[unexpected] STUN addr %q", ipPort) @@ -371,7 +370,7 @@ func (c *Client) GetReport(ctx context.Context) (*Report, error) { if !anyV6() { // IPv6 seemed like it was configured, but actually failed. // Just log and return a nil error. - c.logf("netcheck: IPv6 seemed configured, but no UDP STUN replies") + c.logf("IPv6 seemed configured, but no UDP STUN replies") } return nil } @@ -410,10 +409,48 @@ func (c *Client) GetReport(ctx context.Context) (*Report, error) { report := ret.Clone() c.addReportHistoryAndSetPreferredDERP(report) + c.logConciseReport(report) return report, nil } +func (c *Client) logConciseReport(r *Report) { + buf := bytes.NewBuffer(make([]byte, 0, 256)) // empirically: 5 DERPs + IPv6 == ~233 bytes + fmt.Fprintf(buf, "udp=%v", r.UDP) + fmt.Fprintf(buf, " v6=%v", r.IPv6) + fmt.Fprintf(buf, " mapvarydest=%v", r.MappingVariesByDestIP) + fmt.Fprintf(buf, " hair=%v", r.HairPinning) + if r.GlobalV4 != "" { + fmt.Fprintf(buf, " v4a=%v", r.GlobalV4) + } + if r.GlobalV6 != "" { + fmt.Fprintf(buf, " v6a=%v", r.GlobalV6) + } + fmt.Fprintf(buf, " derp=%v", r.PreferredDERP) + if r.PreferredDERP != 0 { + fmt.Fprintf(buf, " derpdist=") + for i, id := range c.DERP.IDs() { + if i != 0 { + buf.WriteByte(',') + } + s := c.DERP.ServerByID(id) + needComma := false + if d := r.DERPLatency[s.STUN4]; d != 0 { + fmt.Fprintf(buf, "%dv4:%v", id, d.Round(time.Millisecond)) + needComma = true + } + if d := r.DERPLatency[s.STUN6]; d != 0 { + if needComma { + buf.WriteByte(',') + } + fmt.Fprintf(buf, "%dv6:%v", id, d.Round(time.Millisecond)) + } + } + } + + c.logf("%s", buf.Bytes()) +} + func (c *Client) timeNow() time.Time { if c.TimeNow != nil { return c.TimeNow()