From e06862b8d8f26e8261ca8f945e633ffb57439f02 Mon Sep 17 00:00:00 2001 From: Fran Bull Date: Wed, 22 May 2024 09:56:03 -0700 Subject: [PATCH] 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 --- appc/appconnector.go | 52 +++++++++++++++++++++++++++++++++++++++ appc/appconnector_test.go | 49 ++++++++++++++++++++++++++++++++++++ 2 files changed, 101 insertions(+) diff --git a/appc/appconnector.go b/appc/appconnector.go index 91641a294..3f20b5355 100644 --- a/appc/appconnector.go +++ b/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, diff --git a/appc/appconnector_test.go b/appc/appconnector_test.go index c987f7388..f223f8178 100644 --- a/appc/appconnector_test.go +++ b/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") + } +}