diff --git a/control/controlclient/auto.go b/control/controlclient/auto.go index 9ca307bfb..0df6778dc 100644 --- a/control/controlclient/auto.go +++ b/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 diff --git a/control/controlclient/direct.go b/control/controlclient/direct.go index 644430152..fc407e55e 100644 --- a/control/controlclient/direct.go +++ b/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 { diff --git a/ipn/ipnlocal/local.go b/ipn/ipnlocal/local.go index b071120ce..d7480f288 100644 --- a/ipn/ipnlocal/local.go +++ b/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 } diff --git a/logtail/backoff/backoff.go b/logtail/backoff/backoff.go index efc3f7732..269eaf342 100644 --- a/logtail/backoff/backoff.go +++ b/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 { diff --git a/wgengine/monitor/monitor_linux.go b/wgengine/monitor/monitor_linux.go index 5136254f2..d705ed261 100644 --- a/wgengine/monitor/monitor_linux.go +++ b/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),