diff --git a/cmd/tailscaled/debug.go b/cmd/tailscaled/debug.go index 8b142ed00..8208a6e3c 100644 --- a/cmd/tailscaled/debug.go +++ b/cmd/tailscaled/debug.go @@ -143,7 +143,7 @@ func changeDeltaWatcher(ec *eventbus.Client, ctx context.Context, dump func(st * return } log.Printf("Network monitor fired. New state:") - dump(delta.New) + dump(delta.CurrentState()) } } } diff --git a/ipn/ipnlocal/local.go b/ipn/ipnlocal/local.go index 14b1cb035..1c9934fd2 100644 --- a/ipn/ipnlocal/local.go +++ b/ipn/ipnlocal/local.go @@ -560,10 +560,15 @@ func NewLocalBackend(logf logger.Logf, logID logid.PublicID, sys *tsd.System, lo b.e.SetStatusCallback(b.setWgengineStatus) b.interfaceState = netMon.InterfaceState() + // Call our linkChange code once with the current state. // Following changes are triggered via the eventbus. - cd := netmon.NewChangeDelta(nil, b.interfaceState, false, netMon.TailscaleInterfaceName(), false) - b.linkChange(&cd) + cd, err := netmon.NewChangeDelta(nil, b.interfaceState, false, netMon.TailscaleInterfaceName(), false) + if err != nil { + b.logf("[unexpected] setting initial netmon state failed: %v", err) + } else { + b.linkChange(cd) + } if buildfeatures.HasPeerAPIServer { if tunWrap, ok := b.sys.Tun.GetOK(); ok { @@ -962,7 +967,7 @@ func (b *LocalBackend) linkChange(delta *netmon.ChangeDelta) { b.mu.Lock() defer b.mu.Unlock() - b.interfaceState = delta.New + b.interfaceState = delta.CurrentState() b.pauseOrResumeControlClientLocked() prefs := b.pm.CurrentPrefs() @@ -996,7 +1001,7 @@ func (b *LocalBackend) linkChange(delta *netmon.ChangeDelta) { // If the local network configuration has changed, our filter may // need updating to tweak default routes. b.updateFilterLocked(prefs) - updateExitNodeUsageWarning(prefs, delta.New, b.health) + updateExitNodeUsageWarning(prefs, delta.CurrentState(), b.health) if buildfeatures.HasPeerAPIServer { cn := b.currentNode() diff --git a/net/netmon/loghelper.go b/net/netmon/loghelper.go index ce3b9cb87..9f1961d65 100644 --- a/net/netmon/loghelper.go +++ b/net/netmon/loghelper.go @@ -6,38 +6,43 @@ package netmon import ( "context" "sync" + "time" "tailscale.com/types/logger" "tailscale.com/util/eventbus" ) +const cooldownSeconds = 300 + // LinkChangeLogLimiter returns a new [logger.Logf] that logs each unique -// format string to the underlying logger only once per major LinkChange event. +// format string to the underlying logger only once per major LinkChange event +// with a cooldownSeconds second cooldown. // // The logger stops tracking seen format strings when the provided context is // done. func LinkChangeLogLimiter(ctx context.Context, logf logger.Logf, nm *Monitor) logger.Logf { - var formatSeen sync.Map // map[string]bool - sub := eventbus.SubscribeFunc(nm.b, func(cd ChangeDelta) { - // If we're in a major change or a time jump, clear the seen map. - if cd.RebindLikelyRequired || cd.TimeJumped { - formatSeen.Clear() + var formatLastSeen sync.Map // map[string]int64 + + sub := eventbus.SubscribeFunc(nm.b, func(cd *ChangeDelta) { + // Any link changes that are flagged as likely require a rebind are + // interesting enough that we should log them. + if cd.RebindLikelyRequired { + formatLastSeen = sync.Map{} } }) context.AfterFunc(ctx, sub.Close) return func(format string, args ...any) { - // We only store 'true' in the map, so if it's present then it - // means we've already logged this format string. - _, loaded := formatSeen.LoadOrStore(format, true) - if loaded { - // TODO(andrew-d): we may still want to log this - // message every N minutes (1x/hour?) even if it's been - // seen, so that debugging doesn't require searching - // back in the logs for an unbounded amount of time. - // - // See: https://github.com/tailscale/tailscale/issues/13145 - return + // get the current timestamp + now := time.Now().Unix() + lastSeen, ok := formatLastSeen.Load(format) + if ok { + // if we've seen this format string within the last hour, skip logging + if now-lastSeen.(int64) < cooldownSeconds { + return + } } + // update the last seen timestamp for this format string + formatLastSeen.Store(format, now) logf(format, args...) } diff --git a/net/netmon/loghelper_test.go b/net/netmon/loghelper_test.go index 70c3a0706..968c2fd41 100644 --- a/net/netmon/loghelper_test.go +++ b/net/netmon/loghelper_test.go @@ -64,7 +64,14 @@ func syncTestLinkChangeLogLimiter(t *testing.T) { // InjectEvent doesn't work because it's not a major event, so we // instead inject the event ourselves. injector := eventbustest.NewInjector(t, bus) - eventbustest.Inject(injector, NewChangeDelta(nil, nil, true, "", false)) + cd, err := NewChangeDelta(nil, &State{}, true, "tailscale0", true) + if err != nil { + t.Fatal(err) + } + if cd.RebindLikelyRequired != true { + t.Fatalf("expected RebindLikelyRequired to be true, got false") + } + eventbustest.Inject(injector, cd) synctest.Wait() logf("hello %s", "world") diff --git a/net/netmon/netmon.go b/net/netmon/netmon.go index 9e61a5c89..ef0da60ca 100644 --- a/net/netmon/netmon.go +++ b/net/netmon/netmon.go @@ -9,6 +9,7 @@ package netmon import ( "errors" "fmt" + "log" "net/netip" "runtime" "slices" @@ -88,19 +89,14 @@ type ChangeFunc func(*ChangeDelta) // ChangeDelta describes the difference between two network states. // // Use NewChangeDelta to construct a delta and compute the cached fields. -// -// TODO (barnstar): make new and old (and netmon.State) private once all consumers are updated -// to use the accessor methods. type ChangeDelta struct { - // Old is the old interface state, if known. + // old is the old interface state, if known. // It's nil if the old state is unknown. - // Do not mutate it. - Old *State + old *State // New is the new network state. // It is always non-nil. - // Do not mutate it. - New *State + new *State // TimeJumped is whether there was a big jump in wall time since the last // time we checked. This is a hint that a sleeping device might have @@ -130,30 +126,36 @@ type ChangeDelta struct { RebindLikelyRequired bool } +// CurrentState returns the current (new) state after the change. +func (cd *ChangeDelta) CurrentState() *State { + return cd.new +} + // NewChangeDelta builds a ChangeDelta and eagerly computes the cached fields. // forceViability, if true, forces DefaultInterfaceMaybeViable to be true regardless of the // actual state of the default interface. This is useful in testing. -func NewChangeDelta(old, new *State, timeJumped bool, tsIfName string, forceViability bool) ChangeDelta { +func NewChangeDelta(old, new *State, timeJumped bool, tsIfName string, forceViability bool) (*ChangeDelta, error) { cd := ChangeDelta{ - Old: old, - New: new, + old: old, + new: new, TimeJumped: timeJumped, TailscaleIfaceName: tsIfName, } - if cd.New == nil { - return cd - } else if cd.Old == nil { - cd.DefaultInterfaceChanged = cd.New.DefaultRouteInterface != "" + if cd.new == nil { + log.Printf("[unexpected] NewChangeDelta called with nil new state") + return nil, errors.New("new state cannot be nil") + } else if cd.old == nil && cd.new != nil { + cd.DefaultInterfaceChanged = cd.new.DefaultRouteInterface != "" cd.IsLessExpensive = false cd.HasPACOrProxyConfigChanged = true cd.InterfaceIPsChanged = true cd.IsInitialState = true } else { - cd.AvailableProtocolsChanged = (cd.Old.HaveV4 != cd.New.HaveV4) || (cd.Old.HaveV6 != cd.New.HaveV6) - cd.DefaultInterfaceChanged = cd.Old.DefaultRouteInterface != cd.New.DefaultRouteInterface - cd.IsLessExpensive = cd.Old.IsExpensive && !cd.New.IsExpensive - cd.HasPACOrProxyConfigChanged = (cd.Old.PAC != cd.New.PAC) || (cd.Old.HTTPProxy != cd.New.HTTPProxy) + cd.AvailableProtocolsChanged = (cd.old.HaveV4 != cd.new.HaveV4) || (cd.old.HaveV6 != cd.new.HaveV6) + cd.DefaultInterfaceChanged = cd.old.DefaultRouteInterface != cd.new.DefaultRouteInterface + cd.IsLessExpensive = cd.old.IsExpensive && !cd.new.IsExpensive + cd.HasPACOrProxyConfigChanged = (cd.old.PAC != cd.new.PAC) || (cd.old.HTTPProxy != cd.new.HTTPProxy) cd.InterfaceIPsChanged = cd.isInterestingIntefaceChange() } @@ -171,7 +173,7 @@ func NewChangeDelta(old, new *State, timeJumped bool, tsIfName string, forceViab // Compute rebind requirement. The default interface needs to be viable and // one of the other conditions needs to be true. - cd.RebindLikelyRequired = (cd.Old == nil || + cd.RebindLikelyRequired = (cd.old == nil || cd.TimeJumped || cd.DefaultInterfaceChanged || cd.InterfaceIPsChanged || @@ -180,38 +182,38 @@ func NewChangeDelta(old, new *State, timeJumped bool, tsIfName string, forceViab cd.AvailableProtocolsChanged) && cd.DefaultInterfaceMaybeViable - return cd + return &cd, nil } // StateDesc returns a description of the old and new states for logging func (cd *ChangeDelta) StateDesc() string { - return fmt.Sprintf("old: %v new: %v", cd.Old, cd.New) + return fmt.Sprintf("old: %v new: %v", cd.old, cd.new) } // InterfaceIPAppeared reports whether the given IP address exists on any interface // in the old state, but not in the new state. func (cd *ChangeDelta) InterfaceIPDisppeared(ip netip.Addr) bool { - if cd.Old == nil { + if cd.old == nil { return false } - if cd.New == nil && cd.Old.HasIP(ip) { + if cd.new == nil && cd.old.HasIP(ip) { return true } - return cd.New.HasIP(ip) && !cd.Old.HasIP(ip) + return cd.new.HasIP(ip) && !cd.old.HasIP(ip) } // InterfaceIPDisappeared reports whether the given IP address existed on any interface // in the old state, but not in the new state. func (cd *ChangeDelta) InterfaceIPDisappeared(ip netip.Addr) bool { - return !cd.New.HasIP(ip) && cd.Old.HasIP(ip) + return !cd.new.HasIP(ip) && cd.old.HasIP(ip) } // AnyInterfaceUp reports whether any interfaces are up in the new state. func (cd *ChangeDelta) AnyInterfaceUp() bool { - if cd.New == nil { + if cd.new == nil { return false } - for _, ifi := range cd.New.Interface { + for _, ifi := range cd.new.Interface { if ifi.IsUp() { return true } @@ -223,23 +225,23 @@ func (cd *ChangeDelta) AnyInterfaceUp() bool { // This excludes interfaces that are not interesting per IsInterestingInterface and // filters out changes to interface IPs that that are uninteresting (e.g. link-local addresses). func (cd *ChangeDelta) isInterestingIntefaceChange() bool { - if cd.Old == nil && cd.New == nil { + if cd.old == nil && cd.new == nil { return false } // If either side is nil treat as changed. - if cd.Old == nil || cd.New == nil { + if cd.old == nil || cd.new == nil { return true } // Compare interfaces in both directions. Old to new and new to old. - for iname, oldInterface := range cd.Old.Interface { + for iname, oldInterface := range cd.old.Interface { if iname == cd.TailscaleIfaceName { // Ignore changes in the Tailscale interface itself. continue } - oldIps := filterRoutableIPs(cd.Old.InterfaceIPs[iname]) + oldIps := filterRoutableIPs(cd.old.InterfaceIPs[iname]) if IsInterestingInterface != nil && !IsInterestingInterface(oldInterface, oldIps) { continue } @@ -253,11 +255,11 @@ func (cd *ChangeDelta) isInterestingIntefaceChange() bool { // a global unicast IP. That's considered a change from the perspective // of anything that may have been bound to it. If it didn't have a global // unicast IP, it's not interesting. - newInterface, ok := cd.New.Interface[iname] + newInterface, ok := cd.new.Interface[iname] if !ok { return true } - newIps, ok := cd.New.InterfaceIPs[iname] + newIps, ok := cd.new.InterfaceIPs[iname] if !ok { return true } @@ -268,11 +270,11 @@ func (cd *ChangeDelta) isInterestingIntefaceChange() bool { } } - for iname, newInterface := range cd.New.Interface { + for iname, newInterface := range cd.new.Interface { if iname == cd.TailscaleIfaceName { continue } - newIps := filterRoutableIPs(cd.New.InterfaceIPs[iname]) + newIps := filterRoutableIPs(cd.new.InterfaceIPs[iname]) if IsInterestingInterface != nil && !IsInterestingInterface(newInterface, newIps) { continue } @@ -282,12 +284,12 @@ func (cd *ChangeDelta) isInterestingIntefaceChange() bool { continue } - oldInterface, ok := cd.Old.Interface[iname] + oldInterface, ok := cd.old.Interface[iname] if !ok { return true } - oldIps, ok := cd.Old.InterfaceIPs[iname] + oldIps, ok := cd.old.InterfaceIPs[iname] if !ok { // Redundant but we can't dig up the "old" IPs for this interface. return true @@ -315,7 +317,6 @@ func filterRoutableIPs(addrs []netip.Prefix) []netip.Prefix { filtered = append(filtered, pfx) } } - fmt.Printf("Filtered: %v\n", filtered) return filtered } @@ -609,7 +610,11 @@ func (m *Monitor) handlePotentialChange(newState *State, forceCallbacks bool) { return } - delta := NewChangeDelta(oldState, newState, timeJumped, m.tsIfName, false) + delta, err := NewChangeDelta(oldState, newState, timeJumped, m.tsIfName, false) + if err != nil { + m.logf("[unexpected] error creating ChangeDelta: %v", err) + return + } if delta.RebindLikelyRequired { m.gwValid = false @@ -626,9 +631,9 @@ func (m *Monitor) handlePotentialChange(newState *State, forceCallbacks bool) { if delta.TimeJumped { metricChangeTimeJump.Add(1) } - m.changed.Publish(delta) + m.changed.Publish(*delta) for _, cb := range m.cbs { - go cb(&delta) + go cb(delta) } } diff --git a/net/netmon/netmon_test.go b/net/netmon/netmon_test.go index ddffb061a..8fbf512dd 100644 --- a/net/netmon/netmon_test.go +++ b/net/netmon/netmon_test.go @@ -139,7 +139,7 @@ func TestMonitorMode(t *testing.T) { n := 0 mon.RegisterChangeCallback(func(d *ChangeDelta) { n++ - t.Logf("cb: changed=%v, ifSt=%v", d.RebindLikelyRequired, d.New) + t.Logf("cb: changed=%v, ifSt=%v", d.RebindLikelyRequired, d.CurrentState()) }) mon.Start() <-done @@ -150,7 +150,7 @@ func TestMonitorMode(t *testing.T) { mon.Start() eventbustest.Expect(tw, func(event *ChangeDelta) (bool, error) { n++ - t.Logf("cb: changed=%v, ifSt=%v", event.RebindLikelyRequired, event.New) + t.Logf("cb: changed=%v, ifSt=%v", event.RebindLikelyRequired, event.CurrentState()) return false, nil // Return false, indicating we wanna look for more events }) t.Logf("%v events", n) @@ -159,16 +159,13 @@ func TestMonitorMode(t *testing.T) { // tests (*ChangeDelta).RebindRequired func TestRebindRequired(t *testing.T) { + // s1 cannot be nil by definition tests := []struct { name string s1, s2 *State tsIfName string want bool }{ - { - name: "eq_nil", - want: false, - }, { name: "nil_mix", s2: new(State), @@ -498,7 +495,10 @@ func TestRebindRequired(t *testing.T) { } } - cd := NewChangeDelta(tt.s1, tt.s2, false, tt.tsIfName, true) + cd, err := NewChangeDelta(tt.s1, tt.s2, false, tt.tsIfName, true) + if err != nil { + t.Fatalf("NewChangeDelta error: %v", err) + } _ = cd // in case we need it later if got := cd.RebindLikelyRequired; got != tt.want { t.Errorf("RebindRequired = %v; want %v", got, tt.want) diff --git a/net/sockstats/sockstats_tsgo.go b/net/sockstats/sockstats_tsgo.go index ae96218d4..4e9f4a966 100644 --- a/net/sockstats/sockstats_tsgo.go +++ b/net/sockstats/sockstats_tsgo.go @@ -274,7 +274,7 @@ func setNetMon(netMon *netmon.Monitor) { if !delta.RebindLikelyRequired { return } - state := delta.New + state := delta.CurrentState() ifName := state.DefaultRouteInterface if ifName == "" { return