Browse Source

Do not warn about local address failures on every update

localAddrs runs inside every SendUpdate, which fires on lighthouse.interval
and again on every network change via RebindUDPServer. Logging the failure
there meant a persistent failure warned every interval for the life of the
process, once per failing interface.

collectLocalAddrs now returns its failures instead of logging them, which
keeps it stateless and lets the tests assert on errors rather than log
output. The lighthouse holds the previous error and warns only when it
changes, demoting repeats to Debug, matching how handshake_manager handles
repeated send failures.
John Maguire 2 months ago
parent
commit
8589b76e1f
4 changed files with 77 additions and 26 deletions
  1. 9 12
      hostmap.go
  2. 10 13
      hostmap_test.go
  3. 27 1
      lighthouse.go
  4. 31 0
      lighthouse_test.go

+ 9 - 12
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...)
 }

+ 10 - 13
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")
 }

+ 27 - 1
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

+ 31 - 0
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")
+}