appc: log how often routeInfo is stored

So that we have some debugging info if users have trouble with storing
the routeInfo.

Updates #11008

Signed-off-by: Fran Bull <fran@tailscale.com>

appc/appconnector.go

@@ -15,6 +15,7 @@ import (
 	"slices"
 	"strings"
 	"sync"
+	"time"
 
 	xmaps "golang.org/x/exp/maps"
 	"golang.org/x/net/dns/dnsmessage"
@@ -26,6 +27,46 @@ import (
 	"tailscale.com/util/slicesx"
 )
 
+// rateLogger responds to calls to update by adding a count for the current period and
+// calling the callback if any previous period has finished since update was last called
+type rateLogger struct {
+	interval    time.Duration
+	start       time.Time
+	periodStart time.Time
+	periodCount int64
+	now         func() time.Time
+	callback    func(int64, time.Time)
+}
+
+func (rl *rateLogger) currentIntervalStart(now time.Time) time.Time {
+	millisSince := now.Sub(rl.start).Milliseconds() % rl.interval.Milliseconds()
+	return now.Add(-(time.Duration(millisSince)) * time.Millisecond)
+}
+
+func (rl *rateLogger) update() {
+	now := rl.now()
+	periodEnd := rl.periodStart.Add(rl.interval)
+	if periodEnd.Before(now) {
+		if rl.periodCount != 0 {
+			rl.callback(rl.periodCount, rl.periodStart)
+		}
+		rl.periodCount = 0
+		rl.periodStart = rl.currentIntervalStart(now)
+	}
+	rl.periodCount++
+}
+
+func newRateLogger(now func() time.Time, interval time.Duration, callback func(int64, time.Time)) *rateLogger {
+	nowTime := now()
+	return &rateLogger{
+		callback:    callback,
+		now:         now,
+		interval:    interval,
+		start:       nowTime,
+		periodStart: nowTime,
+	}
+}
+
 // RouteAdvertiser is an interface that allows the AppConnector to advertise
 // newly discovered routes that need to be served through the AppConnector.
 type RouteAdvertiser interface {
@@ -81,6 +122,9 @@ type AppConnector struct {
 
 	// queue provides ordering for update operations
 	queue execqueue.ExecQueue
+
+	writeRateMinute *rateLogger
+	writeRateDay    *rateLogger
 }
 
 // NewAppConnector creates a new AppConnector.
@@ -95,6 +139,12 @@ func NewAppConnector(logf logger.Logf, routeAdvertiser RouteAdvertiser, routeInf
 		ac.wildcards = routeInfo.Wildcards
 		ac.controlRoutes = routeInfo.Control
 	}
+	ac.writeRateMinute = newRateLogger(time.Now, time.Minute, func(c int64, s time.Time) {
+		ac.logf("routeInfo write rate: %d in minute starting at %v", c, s)
+	})
+	ac.writeRateDay = newRateLogger(time.Now, 24*time.Hour, func(c int64, s time.Time) {
+		ac.logf("routeInfo write rate: %d in 24 hours starting at %v", c, s)
+	})
 	return ac
 }
 
@@ -109,6 +159,8 @@ func (e *AppConnector) storeRoutesLocked() error {
 	if !e.ShouldStoreRoutes() {
 		return nil
 	}
+	e.writeRateMinute.update()
+	e.writeRateDay.update()
 	return e.storeRoutesFunc(&RouteInfo{
 		Control:   e.controlRoutes,
 		Domains:   e.domains,

appc/appconnector_test.go

@@ -9,10 +9,12 @@ import (
 	"reflect"
 	"slices"
 	"testing"
+	"time"
 
 	xmaps "golang.org/x/exp/maps"
 	"golang.org/x/net/dns/dnsmessage"
 	"tailscale.com/appc/appctest"
+	"tailscale.com/tstest"
 	"tailscale.com/util/mak"
 	"tailscale.com/util/must"
 )
@@ -520,3 +522,50 @@ func TestRoutesWithout(t *testing.T) {
 	assert("a has fewer", routesWithout(prefixes("1.1.1.1/32", "1.1.1.2/32"), prefixes("1.1.1.1/32", "1.1.1.2/32", "1.1.1.3/32", "1.1.1.4/32")), []netip.Prefix{})
 	assert("a has more", routesWithout(prefixes("1.1.1.1/32", "1.1.1.2/32", "1.1.1.3/32", "1.1.1.4/32"), prefixes("1.1.1.1/32", "1.1.1.3/32")), prefixes("1.1.1.2/32", "1.1.1.4/32"))
 }
+
+func TestRateLogger(t *testing.T) {
+	clock := tstest.Clock{}
+	wasCalled := false
+	rl := newRateLogger(func() time.Time { return clock.Now() }, 1*time.Second, func(count int64, _ time.Time) {
+		if count != 3 {
+			t.Fatalf("count for prev period: got %d, want 3", count)
+		}
+		wasCalled = true
+	})
+
+	for i := 0; i < 3; i++ {
+		clock.Advance(1 * time.Millisecond)
+		rl.update()
+		if wasCalled {
+			t.Fatalf("wasCalled: got true, want false")
+		}
+	}
+
+	clock.Advance(1 * time.Second)
+	rl.update()
+	if !wasCalled {
+		t.Fatalf("wasCalled: got false, want true")
+	}
+
+	wasCalled = false
+	rl = newRateLogger(func() time.Time { return clock.Now() }, 1*time.Hour, func(count int64, _ time.Time) {
+		if count != 3 {
+			t.Fatalf("count for prev period: got %d, want 3", count)
+		}
+		wasCalled = true
+	})
+
+	for i := 0; i < 3; i++ {
+		clock.Advance(1 * time.Minute)
+		rl.update()
+		if wasCalled {
+			t.Fatalf("wasCalled: got true, want false")
+		}
+	}
+
+	clock.Advance(1 * time.Hour)
+	rl.update()
+	if !wasCalled {
+		t.Fatalf("wasCalled: got false, want true")
+	}
+}