all: adjust some log verbosity

Updates #1548

Change-Id: Ia55f1b5dc7dfea09a08c90324226fb92cd10fa00
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>

control/controlclient/auto.go

@@ -266,9 +266,9 @@ func (c *Auto) authRoutine() {
 		goal := c.loginGoal
 		ctx := c.authCtx
 		if goal != nil {
-			c.logf("authRoutine: %s; wantLoggedIn=%v", c.state, goal.wantLoggedIn)
+			c.logf("[v1] authRoutine: %s; wantLoggedIn=%v", c.state, goal.wantLoggedIn)
 		} else {
-			c.logf("authRoutine: %s; goal=nil paused=%v", c.state, c.paused)
+			c.logf("[v1] authRoutine: %s; goal=nil paused=%v", c.state, c.paused)
 		}
 		c.mu.Unlock()
 
@@ -414,7 +414,7 @@ func (c *Auto) mapRoutine() {
 			}
 			continue
 		}
-		c.logf("mapRoutine: %s", c.state)
+		c.logf("[v1] mapRoutine: %s", c.state)
 		loggedIn := c.loggedIn
 		ctx := c.mapCtx
 		c.mu.Unlock()
@@ -445,9 +445,9 @@ func (c *Auto) mapRoutine() {
 
 			select {
 			case <-ctx.Done():
-				c.logf("mapRoutine: context done.")
+				c.logf("[v1] mapRoutine: context done.")
 			case <-c.newMapCh:
-				c.logf("mapRoutine: new map needed while idle.")
+				c.logf("[v1] mapRoutine: new map needed while idle.")
 			}
 		} else {
 			// Be sure this is false when we're not inside

control/controlclient/direct.go

@@ -214,7 +214,7 @@ func (c *Direct) SetHostinfo(hi *tailcfg.Hostinfo) bool {
 	}
 	c.hostinfo = hi.Clone()
 	j, _ := json.Marshal(c.hostinfo)
-	c.logf("HostInfo: %s", j)
+	c.logf("[v1] HostInfo: %s", j)
 	return true
 }
 
@@ -245,10 +245,10 @@ func (c *Direct) GetPersist() persist.Persist {
 }
 
 func (c *Direct) TryLogout(ctx context.Context) error {
-	c.logf("direct.TryLogout()")
+	c.logf("[v1] direct.TryLogout()")
 
 	mustRegen, newURL, err := c.doLogin(ctx, loginOpt{Logout: true})
-	c.logf("TryLogout control response: mustRegen=%v, newURL=%v, err=%v", mustRegen, newURL, err)
+	c.logf("[v1] TryLogout control response: mustRegen=%v, newURL=%v, err=%v", mustRegen, newURL, err)
 
 	c.mu.Lock()
 	c.persist = persist.Persist{}
@@ -258,7 +258,7 @@ func (c *Direct) TryLogout(ctx context.Context) error {
 }
 
 func (c *Direct) TryLogin(ctx context.Context, t *tailcfg.Oauth2Token, flags LoginFlags) (url string, err error) {
-	c.logf("direct.TryLogin(token=%v, flags=%v)", t != nil, flags)
+	c.logf("[v1] direct.TryLogin(token=%v, flags=%v)", t != nil, flags)
 	return c.doLoginOrRegen(ctx, loginOpt{Token: t, Flags: flags})
 }
 
@@ -266,7 +266,7 @@ func (c *Direct) TryLogin(ctx context.Context, t *tailcfg.Oauth2Token, flags Log
 //
 // On success, newURL and err will both be nil.
 func (c *Direct) WaitLoginURL(ctx context.Context, url string) (newURL string, err error) {
-	c.logf("direct.WaitLoginURL")
+	c.logf("[v1] direct.WaitLoginURL")
 	return c.doLoginOrRegen(ctx, loginOpt{URL: url})
 }
 
@@ -469,7 +469,7 @@ func (c *Direct) doLogin(ctx context.Context, opt loginOpt) (mustRegen bool, new
 	if resp.AuthURL != "" {
 		c.logf("AuthURL is %v", resp.AuthURL)
 	} else {
-		c.logf("No AuthURL")
+		c.logf("[v1] No AuthURL")
 	}
 
 	c.mu.Lock()
@@ -520,7 +520,7 @@ func (c *Direct) newEndpoints(localPort uint16, endpoints []tailcfg.Endpoint) (c
 	for _, ep := range endpoints {
 		epStrs = append(epStrs, ep.Addr.String())
 	}
-	c.logf("client.newEndpoints(%v, %v)", localPort, epStrs)
+	c.logf("[v2] client.newEndpoints(%v, %v)", localPort, epStrs)
 	c.localPort = localPort
 	c.endpoints = append(c.endpoints[:0], endpoints...)
 	if len(endpoints) > 0 {

ipn/ipnlocal/local.go

@@ -906,7 +906,7 @@ func (b *LocalBackend) Start(opts ipn.Options) error {
 			timer := time.NewTimer(time.Second)
 			select {
 			case <-b.gotPortPollRes:
-				b.logf("got initial portlist info in %v", time.Since(t0).Round(time.Millisecond))
+				b.logf("[v1] got initial portlist info in %v", time.Since(t0).Round(time.Millisecond))
 				timer.Stop()
 			case <-timer.C:
 				b.logf("timeout waiting for initial portlist")
@@ -1054,17 +1054,17 @@ func (b *LocalBackend) updateFilter(netMap *netmap.NetworkMap, prefs *ipn.Prefs)
 	}
 
 	if !haveNetmap {
-		b.logf("netmap packet filter: (not ready yet)")
+		b.logf("[v1] netmap packet filter: (not ready yet)")
 		b.setFilter(filter.NewAllowNone(b.logf, logNets))
 		return
 	}
 
 	oldFilter := b.e.GetFilter()
 	if shieldsUp {
-		b.logf("netmap packet filter: (shields up)")
+		b.logf("[v1] netmap packet filter: (shields up)")
 		b.setFilter(filter.NewShieldsUpFilter(localNets, logNets, oldFilter, b.logf))
 	} else {
-		b.logf("netmap packet filter: %v filters", len(packetFilter))
+		b.logf("[v1] netmap packet filter: %v filters", len(packetFilter))
 		b.setFilter(filter.New(packetFilter, localNets, logNets, oldFilter, b.logf))
 	}
 }
@@ -1503,19 +1503,19 @@ func (b *LocalBackend) loadStateLocked(key ipn.StateKey, prefs *ipn.Prefs) (err
 		}
 	}
 
-	b.logf("using backend prefs")
 	bs, err := b.store.ReadState(key)
 	switch {
 	case errors.Is(err, ipn.ErrStateNotExist):
 		b.prefs = ipn.NewPrefs()
 		b.prefs.WantRunning = false
-		b.logf("created empty state for %q: %s", key, b.prefs.Pretty())
+		b.logf("using backend prefs; created empty state for %q: %s", key, b.prefs.Pretty())
 		return nil
 	case err != nil:
-		return fmt.Errorf("store.ReadState(%q): %v", key, err)
+		return fmt.Errorf("backend prefs: store.ReadState(%q): %v", key, err)
 	}
 	b.prefs, err = ipn.PrefsFromBytes(bs, false)
 	if err != nil {
+		b.logf("using backend prefs for %q", key)
 		return fmt.Errorf("PrefsFromBytes: %v", err)
 	}
 
@@ -1538,7 +1538,7 @@ func (b *LocalBackend) loadStateLocked(key ipn.StateKey, prefs *ipn.Prefs) (err
 		}
 	}
 
-	b.logf("backend prefs for %q: %s", key, b.prefs.Pretty())
+	b.logf("using backend prefs for %q: %s", key, b.prefs.Pretty())
 
 	b.sshAtomicBool.Set(b.prefs != nil && b.prefs.RunSSH)
 
@@ -1916,15 +1916,15 @@ func (b *LocalBackend) authReconfig() {
 	b.mu.Unlock()
 
 	if blocked {
-		b.logf("authReconfig: blocked, skipping.")
+		b.logf("[v1] authReconfig: blocked, skipping.")
 		return
 	}
 	if nm == nil {
-		b.logf("authReconfig: netmap not yet valid. Skipping.")
+		b.logf("[v1] authReconfig: netmap not yet valid. Skipping.")
 		return
 	}
 	if !prefs.WantRunning {
-		b.logf("authReconfig: skipping because !WantRunning.")
+		b.logf("[v1] authReconfig: skipping because !WantRunning.")
 		return
 	}
 

logtail/backoff/backoff.go

@@ -71,7 +71,7 @@ func (b *Backoff) BackOff(ctx context.Context, err error) {
 	d = time.Duration(float64(d) * (rand.Float64() + 0.5))
 
 	if d >= b.LogLongerThan {
-		b.logf("%s: backoff: %d msec", b.name, d.Milliseconds())
+		b.logf("%s: [v1] backoff: %d msec", b.name, d.Milliseconds())
 	}
 	t := b.NewTimer(d)
 	select {

wgengine/monitor/monitor_linux.go

@@ -101,9 +101,21 @@ func (c *nlConn) Receive() (message, error) {
 		dst := netaddrIPPrefix(rmsg.Attributes.Dst, rmsg.DstLength)
 		gw := netaddrIP(rmsg.Attributes.Gateway)
 
+		if msg.Header.Type == unix.RTM_NEWROUTE &&
+			(rmsg.Attributes.Table == 255 || rmsg.Attributes.Table == 254) &&
+			(dst.IP().IsMulticast() || dst.IP().IsLinkLocalUnicast()) {
+			// Normal Linux route changes on new interface coming up; don't log or react.
+			return ignoreMessage{}, nil
+		}
+
 		if rmsg.Table == tsTable && dst.IsSingleIP() {
 			// Don't log. Spammy and normal to see a bunch of these on start-up,
 			// which we make ourselves.
+		} else if tsaddr.IsTailscaleIP(dst.IP()) {
+			// Verbose only.
+			c.logf("%s: [v1] src=%v, dst=%v, gw=%v, outif=%v, table=%v", typeStr,
+				condNetAddrPrefix(src), condNetAddrPrefix(dst), condNetAddrIP(gw),
+				rmsg.Attributes.OutIface, rmsg.Attributes.Table)
 		} else {
 			c.logf("%s: src=%v, dst=%v, gw=%v, outif=%v, table=%v", typeStr,
 				condNetAddrPrefix(src), condNetAddrPrefix(dst), condNetAddrIP(gw),