policy, state: log only the routes auto-approval adds

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")
 		}

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},

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.

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"