From 05039d339834df417a68374282638ba35b90a535 Mon Sep 17 00:00:00 2001 From: Kristoffer Dalby Date: Sat, 17 Oct 2026 10:43:29 +0000 Subject: [PATCH] policy, state: log only the routes auto-approval adds --- hscontrol/policy/policy.go | 7 +-- hscontrol/policy/route_approval_test.go | 74 +++++++++++++++++++++++++ hscontrol/state/state.go | 9 --- hscontrol/util/zlog/zf/fields.go | 3 - 4 files changed, 76 insertions(+), 17 deletions(-) diff --git a/hscontrol/policy/policy.go b/hscontrol/policy/policy.go index c3e6741ca..e98af4fe8 100644 --- a/hscontrol/policy/policy.go +++ b/hscontrol/policy/policy.go @@ -68,7 +68,7 @@ func ApproveRoutesWithPolicy(pm PolicyManager, nv types.NodeView, currentApprove // Only update if the routes actually changed if !slices.Equal(sortedCurrent, newApproved) { // Log what changed - var added, kept []netip.Prefix + var added []netip.Prefix for _, route := range newApproved { _, exists := slices.BinarySearchFunc( @@ -76,16 +76,13 @@ func ApproveRoutesWithPolicy(pm PolicyManager, nv types.NodeView, currentApprove ) if !exists { added = append(added, route) - } else { - kept = append(kept, route) } } if len(added) > 0 { - log.Debug(). + log.Info(). EmbedObject(nv). Strs("routes.added", util.PrefixesToString(added)). - Strs("routes.kept", util.PrefixesToString(kept)). Int("routes.total", len(newApproved)). Msg("Routes auto-approved by policy") } diff --git a/hscontrol/policy/route_approval_test.go b/hscontrol/policy/route_approval_test.go index 25a3b6e76..c12a5f0f8 100644 --- a/hscontrol/policy/route_approval_test.go +++ b/hscontrol/policy/route_approval_test.go @@ -1,16 +1,90 @@ package policy import ( + "bytes" + "encoding/json" "fmt" "net/netip" + "strings" "testing" "github.com/google/go-cmp/cmp" "github.com/juanfont/headscale/hscontrol/types" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) +func TestApproveRoutesWithPolicyLogsAddedRoutes(t *testing.T) { + current := make([]netip.Prefix, 1000) + for i := range current { + current[i] = netip.PrefixFrom(netip.AddrFrom4([4]byte{ + 10, byte(i >> 8), byte(i & 0xff), 0, + }), 24) + } + + added := netip.MustParsePrefix("10.200.0.0/24") + user := types.User{ID: 1, Name: "router"} + node := &types.Node{ + ID: 1, + IPv4: new(netip.MustParseAddr("100.64.0.1")), + UserID: new(user.ID), + User: new(user), + ApprovedRoutes: current, + } + pm, err := NewPolicyManager([]byte(`{ + "acls": [], + "autoApprovers": {"routes": {"10.0.0.0/8": ["router@"]}} + }`), []types.User{user}, types.Nodes{node}.ViewSlice()) + require.NoError(t, err) + + var output bytes.Buffer + + originalLogger := log.Logger + originalLevel := zerolog.GlobalLevel() + log.Logger = zerolog.New(&output).Level(zerolog.InfoLevel) + zerolog.SetGlobalLevel(zerolog.InfoLevel) + + t.Cleanup(func() { + log.Logger = originalLogger + + zerolog.SetGlobalLevel(originalLevel) + }) + + approved, changed := ApproveRoutesWithPolicy( + pm, node.View(), current, []netip.Prefix{added}, + ) + require.True(t, changed) + require.Len(t, approved, 1001) + + _, changed = ApproveRoutesWithPolicy( + pm, node.View(), approved, []netip.Prefix{added}) + require.False(t, changed) + require.NotEmpty(t, output.String(), "expected one info log for the new approval") + + lines := strings.Split(strings.TrimSpace(output.String()), "\n") + require.Len(t, lines, 1) + + var entry struct { + Level string `json:"level"` + Node types.NodeID `json:"node.id"` + Added []string `json:"routes.added"` + Total int `json:"routes.total"` + } + + require.NoError(t, json.Unmarshal([]byte(lines[0]), &entry)) + assert.Equal(t, "info", entry.Level) + assert.Equal(t, node.ID, entry.Node) + assert.Equal(t, []string{added.String()}, entry.Added) + assert.Equal(t, 1001, entry.Total) + assert.NotContains(t, output.String(), "routes.kept") + + for _, route := range current { + assert.NotContains(t, output.String(), route.String()) + } +} + func TestNodeCanApproveRoute(t *testing.T) { users := []types.User{ {Name: "user1", ID: 1}, diff --git a/hscontrol/state/state.go b/hscontrol/state/state.go index d503d7436..3c718b312 100644 --- a/hscontrol/state/state.go +++ b/hscontrol/state/state.go @@ -1529,8 +1529,6 @@ func (s *State) AutoApproveRoutes(nv types.NodeView) (change.Change, error) { return c, err } - log.Info().EmbedObject(nv).Strs(zf.RoutesApproved, util.PrefixesToString(approved)).Msg("routes approved") - return c, nil } @@ -3864,13 +3862,6 @@ func (s *State) UpdateNodeFromMapRequest(id types.NodeID, req tailcfg.MapRequest } if routeChange { - log.Info(). - Uint64(zf.NodeID, id.Uint64()). - Strs(zf.OldApprovedRoutes, util.PrefixesToString(currentNode.ApprovedRoutes)). - Strs(zf.NewApprovedRoutes, util.PrefixesToString(autoApprovedRoutes)). - Bool(zf.RouteChanged, routeChange). - Msg("applying route approval results") - // Approving in this write keeps one request at one NodeStore // write, one peer build and one row update. Persisting is // already due: route approval only runs on a Hostinfo change. diff --git a/hscontrol/util/zlog/zf/fields.go b/hscontrol/util/zlog/zf/fields.go index 156d156c7..89da7399e 100644 --- a/hscontrol/util/zlog/zf/fields.go +++ b/hscontrol/util/zlog/zf/fields.go @@ -91,14 +91,11 @@ const ( // Route fields. const ( RoutesAnnounced = "routes.announced" - RoutesApproved = "routes.approved" RoutesApprovedOld = "routes.approved.old" RoutesApprovedNew = "routes.approved.new" OldAnnouncedRoutes = "oldAnnouncedRoutes" NewAnnouncedRoutes = "newAnnouncedRoutes" ApprovedRoutes = "approvedRoutes" - OldApprovedRoutes = "oldApprovedRoutes" - NewApprovedRoutes = "newApprovedRoutes" AutoApprovedRoutes = "autoApprovedRoutes" AllApprovedRoutes = "allApprovedRoutes" RouteChanged = "routeChanged"