diff --git a/hostmap.go b/hostmap.go index 7feb9f55..b82e3f14 100644 --- a/hostmap.go +++ b/hostmap.go @@ -868,26 +868,26 @@ func (i *HostInfo) logger(l *slog.Logger) *slog.Logger { // Utility functions -func localAddrs(l *slog.Logger, allowList *LocalAllowList) []netip.Addr { +func localAddrs(l *slog.Logger, allowList *LocalAllowList) ([]netip.Addr, error) { return collectLocalAddrs(l, allowList, localInterfaces, localInterfaceAddrs) } // collectLocalAddrs takes its enumerators as arguments so tests can drive the filtering and the -// failure branches without depending on the addresses of whatever host they run on. +// failure branches without depending on the addresses of whatever host they run on. It reports +// failures to the caller rather than logging them, because it runs on every lighthouse update and +// only the caller can tell a new failure from a repeat of the same one. func collectLocalAddrs( l *slog.Logger, allowList *LocalAllowList, interfaces func() ([]net.Interface, error), interfaceAddrs func(*net.Interface) ([]net.Addr, error), -) []netip.Addr { +) ([]netip.Addr, error) { //FIXME: This function is pretty garbage var finalAddrs []netip.Addr + var errs []error ifaces, err := interfaces() if err != nil { - l.Warn("Failed to enumerate local interfaces, no underlay addresses will be advertised to lighthouses", - "error", err, - ) - return nil + return nil, fmt.Errorf("failed to enumerate local interfaces: %w", err) } for _, i := range ifaces { @@ -904,10 +904,7 @@ func collectLocalAddrs( } addrs, err := interfaceAddrs(&i) if err != nil { - l.Warn("Failed to get addresses for local interface", - "error", err, - "interfaceName", i.Name, - ) + errs = append(errs, fmt.Errorf("failed to get addresses for %s: %w", i.Name, err)) continue } @@ -945,5 +942,5 @@ func collectLocalAddrs( } } } - return finalAddrs + return finalAddrs, errors.Join(errs...) } diff --git a/hostmap_test.go b/hostmap_test.go index b4991684..9e9c8553 100644 --- a/hostmap_test.go +++ b/hostmap_test.go @@ -1,7 +1,6 @@ package nebula import ( - "bytes" "errors" "net" "net/netip" @@ -430,7 +429,8 @@ func TestCollectLocalAddrs(t *testing.T) { addrsFor := func(i *net.Interface) ([]net.Addr, error) { return addrs[i.Name], nil } // Loopback and link local are dropped, everything else on every interface is kept. - out := collectLocalAddrs(test.NewLogger(), nil, enumerate, addrsFor) + out, err := collectLocalAddrs(test.NewLogger(), nil, enumerate, addrsFor) + require.NoError(t, err) assert.Equal(t, []netip.Addr{ netip.MustParseAddr("10.0.0.5"), netip.MustParseAddr("fd00::5"), @@ -450,7 +450,8 @@ func TestCollectLocalAddrs(t *testing.T) { asked[i.Name] = struct{}{} return addrs[i.Name], nil } - out = collectLocalAddrs(test.NewLogger(), al, enumerate, countingAddrsFor) + out, err = collectLocalAddrs(test.NewLogger(), al, enumerate, countingAddrsFor) + require.NoError(t, err) assert.Equal(t, []netip.Addr{ netip.MustParseAddr("10.0.0.5"), netip.MustParseAddr("fd00::5"), @@ -458,21 +459,18 @@ func TestCollectLocalAddrs(t *testing.T) { assert.NotContains(t, asked, "docker0") // A failure to enumerate interfaces at all is reported rather than silently advertising nothing. - logOut := &bytes.Buffer{} - out = collectLocalAddrs( - test.NewLoggerWithOutput(logOut), + out, err = collectLocalAddrs( + test.NewLogger(), nil, func() ([]net.Interface, error) { return nil, errors.New("netlinkrib: permission denied") }, addrsFor, ) assert.Nil(t, out) - assert.Contains(t, logOut.String(), "Failed to enumerate local interfaces") - assert.Contains(t, logOut.String(), "netlinkrib: permission denied") + require.EqualError(t, err, "failed to enumerate local interfaces: netlinkrib: permission denied") // One interface failing is reported and skipped, the rest are still collected. - logOut.Reset() - out = collectLocalAddrs( - test.NewLoggerWithOutput(logOut), + out, err = collectLocalAddrs( + test.NewLogger(), nil, enumerate, func(i *net.Interface) ([]net.Addr, error) { @@ -483,6 +481,5 @@ func TestCollectLocalAddrs(t *testing.T) { }, ) assert.Equal(t, []netip.Addr{netip.MustParseAddr("172.17.0.1")}, out) - assert.Contains(t, logOut.String(), "Failed to get addresses for local interface") - assert.Contains(t, logOut.String(), "eth0") + require.EqualError(t, err, "failed to get addresses for eth0: nope") } diff --git a/lighthouse.go b/lighthouse.go index 9cece233..4fd002bc 100644 --- a/lighthouse.go +++ b/lighthouse.go @@ -40,6 +40,10 @@ type LightHouse struct { // addresses rather than whatever this machine's NICs happen to be. Set it before Start. localAddrsFn func(*LocalAllowList) []netip.Addr + // lastLocalAddrsErr is the previous localAddrsFn failure. Enumeration runs on every update, so an + // unchanged failure is demoted to Debug rather than warning every lighthouse.interval forever. + lastLocalAddrsErr atomic.Pointer[string] + // Local cache of answers from light houses // map of vpn addr to answers addrMap map[netip.Addr]*RemoteList @@ -112,7 +116,9 @@ func NewLightHouseFromConfig(ctx context.Context, l *slog.Logger, c *config.C, c l: l, } h.localAddrsFn = func(al *LocalAllowList) []netip.Addr { - return localAddrs(h.l, al) + addrs, err := localAddrs(h.l, al) + h.logLocalAddrsErr(err) + return addrs } lighthouses := make([]netip.Addr, 0) @@ -913,6 +919,26 @@ func (lh *LightHouse) TriggerUpdate() { } } +// logLocalAddrsErr reports a localAddrs failure at Warn the first time it is seen and at Debug while +// it persists unchanged, so a permanent failure does not warn on every update forever. +func (lh *LightHouse) logLocalAddrsErr(err error) { + if err == nil { + lh.lastLocalAddrsErr.Store(nil) + return + } + + msg := err.Error() + prev := lh.lastLocalAddrsErr.Swap(&msg) + if prev != nil && *prev == msg { + if lh.l.Enabled(context.Background(), slog.LevelDebug) { + lh.l.Debug("Failed to collect local addresses to advertise", "error", err) + } + return + } + + lh.l.Warn("Failed to collect local addresses to advertise", "error", err) +} + func (lh *LightHouse) SendUpdate() { var v4 []*V4AddrPort var v6 []*V6AddrPort diff --git a/lighthouse_test.go b/lighthouse_test.go index 81c883ff..e530d6bc 100644 --- a/lighthouse_test.go +++ b/lighthouse_test.go @@ -1,7 +1,9 @@ package nebula import ( + "bytes" "encoding/binary" + "errors" "fmt" "net/netip" "testing" @@ -738,3 +740,32 @@ func TestLighthouse_DeletesWork(t *testing.T) { out = lh.Query(testHost) assert.Nil(t, out) } + +func TestLightHouse_logLocalAddrsErr(t *testing.T) { + out := &bytes.Buffer{} + lh := &LightHouse{l: test.NewLoggerWithOutput(out)} + + // The first sighting of a failure warns. + lh.logLocalAddrsErr(errors.New("permission denied")) + assert.Contains(t, out.String(), "level=WARN") + assert.Contains(t, out.String(), "permission denied") + + // Repeating unchanged does not warn again, which is what keeps a permanent failure from warning + // on every lighthouse.interval for the life of the process. + out.Reset() + lh.logLocalAddrsErr(errors.New("permission denied")) + assert.NotContains(t, out.String(), "level=WARN") + + // A different failure is a new event and warns. + out.Reset() + lh.logLocalAddrsErr(errors.New("something else")) + assert.Contains(t, out.String(), "level=WARN") + assert.Contains(t, out.String(), "something else") + + // Recovering resets, so the same failure returning later warns again. + out.Reset() + lh.logLocalAddrsErr(nil) + assert.Empty(t, out.String()) + lh.logLocalAddrsErr(errors.New("something else")) + assert.Contains(t, out.String(), "level=WARN") +}