|
| 1 | +//go:build !race |
| 2 | + |
| 3 | +// This is a timing-sensitive performance regression test; the race detector's |
| 4 | +// ~10x slowdown makes its wall-clock assertion meaningless, so it is excluded |
| 5 | +// from -race builds. The concurrency correctness of the policy lock change it |
| 6 | +// guards is covered under -race by TestPolicyManagerConcurrentReads in |
| 7 | +// hscontrol/policy/v2. |
| 8 | + |
| 9 | +package mapper |
| 10 | + |
| 11 | +import ( |
| 12 | + "net/netip" |
| 13 | + "runtime" |
| 14 | + "slices" |
| 15 | + "sync" |
| 16 | + "testing" |
| 17 | + "time" |
| 18 | + |
| 19 | + "github.com/juanfont/headscale/hscontrol/db" |
| 20 | + "github.com/juanfont/headscale/hscontrol/derp" |
| 21 | + "github.com/juanfont/headscale/hscontrol/state" |
| 22 | + "github.com/juanfont/headscale/hscontrol/types" |
| 23 | + "github.com/stretchr/testify/assert" |
| 24 | + "github.com/stretchr/testify/require" |
| 25 | + "tailscale.com/tailcfg" |
| 26 | +) |
| 27 | + |
| 28 | +// setupStormBatcher builds a real state+batcher with production-default |
| 29 | +// NodeStore batching so the reconnect-storm contention is realistic. It mirrors |
| 30 | +// setupBatcherWithTestData but lets the test control BatcherWorkers and the |
| 31 | +// policy. |
| 32 | +func setupStormBatcher(tb testing.TB, nodeCount, workers int, policy string) (*TestData, func()) { |
| 33 | + tb.Helper() |
| 34 | + |
| 35 | + tmpDir := tb.TempDir() |
| 36 | + prefixV4 := netip.MustParsePrefix("100.64.0.0/10") |
| 37 | + prefixV6 := netip.MustParsePrefix("fd7a:115c:a1e0::/48") |
| 38 | + |
| 39 | + cfg := &types.Config{ |
| 40 | + Database: types.DatabaseConfig{ |
| 41 | + Type: types.DatabaseSqlite, |
| 42 | + Sqlite: types.SqliteConfig{Path: tmpDir + "/headscale_test.db"}, |
| 43 | + }, |
| 44 | + PrefixV4: &prefixV4, |
| 45 | + PrefixV6: &prefixV6, |
| 46 | + IPAllocation: types.IPAllocationStrategySequential, |
| 47 | + BaseDomain: "headscale.test", |
| 48 | + Policy: types.PolicyConfig{Mode: types.PolicyModeDB}, |
| 49 | + DERP: types.DERPConfig{ |
| 50 | + ServerEnabled: false, |
| 51 | + DERPMap: &tailcfg.DERPMap{ |
| 52 | + Regions: map[int]*tailcfg.DERPRegion{999: {RegionID: 999}}, |
| 53 | + }, |
| 54 | + }, |
| 55 | + Tuning: types.Tuning{ |
| 56 | + BatchChangeDelay: 10 * time.Millisecond, |
| 57 | + BatcherWorkers: workers, |
| 58 | + // Production defaults: coalesce writes so the storm is not |
| 59 | + // exaggerated by an unrealistically small NodeStore batch. |
| 60 | + NodeStoreBatchSize: 100, |
| 61 | + NodeStoreBatchTimeout: 500 * time.Millisecond, |
| 62 | + }, |
| 63 | + } |
| 64 | + |
| 65 | + database, err := db.NewHeadscaleDatabase(cfg) |
| 66 | + require.NoError(tb, err) |
| 67 | + |
| 68 | + users := database.CreateUsersForTest(1, "testuser") |
| 69 | + dbNodes := database.CreateRegisteredNodesForTest(users[0], nodeCount, "node") |
| 70 | + |
| 71 | + allNodes := make([]node, 0, nodeCount) |
| 72 | + for i := range dbNodes { |
| 73 | + allNodes = append(allNodes, node{ |
| 74 | + n: dbNodes[i], |
| 75 | + ch: make(chan *tailcfg.MapResponse, normalBufferSize), |
| 76 | + }) |
| 77 | + } |
| 78 | + |
| 79 | + st, err := state.NewState(cfg) |
| 80 | + require.NoError(tb, err) |
| 81 | + |
| 82 | + derpMap, err := derp.GetDERPMap(cfg.DERP) |
| 83 | + require.NoError(tb, err) |
| 84 | + st.SetDERPMap(derpMap) |
| 85 | + |
| 86 | + _, err = st.SetPolicy([]byte(policy)) |
| 87 | + require.NoError(tb, err) |
| 88 | + |
| 89 | + batcher := wrapBatcherForTest(NewBatcherAndMapper(cfg, st), st) |
| 90 | + batcher.Start() |
| 91 | + |
| 92 | + td := &TestData{ |
| 93 | + Database: database, |
| 94 | + Users: users, |
| 95 | + Nodes: allNodes, |
| 96 | + State: st, |
| 97 | + Config: cfg, |
| 98 | + Batcher: batcher, |
| 99 | + } |
| 100 | + |
| 101 | + return td, func() { |
| 102 | + batcher.Close() |
| 103 | + st.Close() |
| 104 | + database.Close() |
| 105 | + } |
| 106 | +} |
| 107 | + |
| 108 | +// TestInitialMapNotStarvedByReconnectStorm reproduces juanfont/headscale#3346. |
| 109 | +// |
| 110 | +// When every node redials at once (e.g. after a server upgrade restart), each |
| 111 | +// connection writes the NodeStore (UpdateNodeFromMapRequest + Connect) and the |
| 112 | +// batcher generates its initial map. All of that reads the policy through the |
| 113 | +// PolicyManager. Before the fix the PolicyManager guarded every read with a |
| 114 | +// single exclusive mutex, so the NodeStore writer's O(n^2) BuildPeerMap and |
| 115 | +// every node's FilterForNode serialised against each other. On a per-node |
| 116 | +// filter policy (autogroup:self, via, relay grants) each hold is expensive, so |
| 117 | +// under the storm time-to-initial-map grew without bound. |
| 118 | +// |
| 119 | +// On the production server in #3346 this drove the batcher's per-node |
| 120 | +// total.duration from ~4s to ~76s; tailscale clients aborted the map POST |
| 121 | +// first and reported |
| 122 | +// |
| 123 | +// PollNetMap: Post ".../machine/map": unexpected EOF |
| 124 | +// |
| 125 | +// then redialled, feeding the storm so it never converged. An allow-all policy |
| 126 | +// does NOT reproduce this — BuildPeerMap is cheap there; the per-node filter |
| 127 | +// path is what makes it expensive, matching a real deployment's ACLs. |
| 128 | +// |
| 129 | +// The fix makes PolicyManager reads take a shared RLock so map generation runs |
| 130 | +// concurrently. AddNode blocks until the initial map is generated and handed to |
| 131 | +// the node channel, so its wall-clock duration is the time-to-initial-map the |
| 132 | +// client experiences. Without the fix this test's slowest node takes ~10s+ at |
| 133 | +// this scale (lock-bound, and more workers do not help); with it, generation |
| 134 | +// parallelises across workers and stays well within a client's patience. |
| 135 | +func TestInitialMapNotStarvedByReconnectStorm(t *testing.T) { |
| 136 | + if testing.Short() { |
| 137 | + t.Skip("timing-sensitive storm regression; skipped in -short") |
| 138 | + } |
| 139 | + |
| 140 | + const ( |
| 141 | + nodeCount = 300 |
| 142 | + |
| 143 | + // A per-node-filter policy: forces BuildPeerMap and FilterForNode onto |
| 144 | + // the slow path that recompiles filter rules per node, the same shape |
| 145 | + // as a real ACL using autogroup:self / via / relay grants. |
| 146 | + perNodeFilterPolicy = `{"acls":[{"action":"accept","src":["autogroup:member"],"dst":["autogroup:self:*"]}]}` |
| 147 | + |
| 148 | + // Generous bound: post-fix the slowest node lands at ~2-5s depending on |
| 149 | + // core count; pre-fix it is lock-bound at ~10s+ regardless of workers. |
| 150 | + maxAcceptableLatency = 8 * time.Second |
| 151 | + ) |
| 152 | + |
| 153 | + // Use the real available parallelism, as production does; the fix's win is |
| 154 | + // that generation scales with it instead of serialising on the policy lock. |
| 155 | + workers := runtime.NumCPU() |
| 156 | + |
| 157 | + td, cleanup := setupStormBatcher(t, nodeCount, workers, perNodeFilterPolicy) |
| 158 | + defer cleanup() |
| 159 | + |
| 160 | + latencies := make([]time.Duration, nodeCount) |
| 161 | + |
| 162 | + var wg sync.WaitGroup |
| 163 | + |
| 164 | + for i := range td.Nodes { |
| 165 | + wg.Go(func() { |
| 166 | + n := &td.Nodes[i] |
| 167 | + |
| 168 | + start := time.Now() |
| 169 | + err := td.Batcher.AddNode(n.n.ID, n.ch, tailcfg.CapabilityVersion(100), nil) |
| 170 | + latencies[i] = time.Since(start) |
| 171 | + |
| 172 | + assert.NoError(t, err) //nolint:testifylint // assert (not require) is correct off the test goroutine |
| 173 | + }) |
| 174 | + } |
| 175 | + |
| 176 | + wg.Wait() |
| 177 | + |
| 178 | + slices.Sort(latencies) |
| 179 | + p50 := latencies[len(latencies)/2] |
| 180 | + p95 := latencies[len(latencies)*95/100] |
| 181 | + maxLatency := latencies[len(latencies)-1] |
| 182 | + t.Logf("initial-map latency over %d nodes (workers=%d): p50=%s p95=%s max=%s", |
| 183 | + nodeCount, workers, p50, p95, maxLatency) |
| 184 | + |
| 185 | + require.Less(t, maxLatency, maxAcceptableLatency, |
| 186 | + "slowest initial map took %s: policy reads are serialising instead of running concurrently (issue #3346)", maxLatency) |
| 187 | +} |
0 commit comments