| 1 | package activator |
| 2 | |
| 3 | import ( |
| 4 | "context" |
| 5 | "errors" |
| 6 | "log" |
| 7 | "os" |
| 8 | "slices" |
| 9 | "strings" |
| 10 | "sync" |
| 11 | "testing" |
| 12 | "time" |
| 13 | ) |
| 14 | |
| 15 | // Discussion #292, the production sequence with swaps off. `systemctl |
| 16 | // restart carlos-edge` stops every carlos-instance@ unit first |
| 17 | // (BindsTo= and After=carlos-edge.service), while the old agent is still |
| 18 | // running and has not had its SIGTERM. The agent sees the child gone, |
| 19 | // recycles the entry and gives its lease back, and a request queued on |
| 20 | // the stop wakes the host again, taking a fresh lease. That wake's start |
| 21 | // is a systemctl start job systemd queues behind the edge restart, so it |
| 22 | // is still in flight when the SIGTERM arrives. Shutdown has to abort it |
| 23 | // and give its lease back before the process exits; otherwise the next |
| 24 | // agent refuses the host for the lease's whole TTL. |
| 25 | // |
| 26 | // Aborting the client's start does not abort the start job systemd queued |
| 27 | // (Astra, review of 9a8e295c, P1): released over that job, the lease would |
| 28 | // let the job launch a writer nobody holds a lease for. So the abort stops |
| 29 | // the unit and proves it gone first, and only then gives the lease back. |
| 30 | func TestShutdownAbortsAWakeAndReleasesItsLease(t *testing.T) { |
| 31 | t.Parallel() |
| 32 | a, b, reqErr := arrangeQueuedRewake(t, "restart.example.com") |
| 33 | |
| 34 | ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) |
| 35 | defer cancel() |
| 36 | a.Shutdown(ctx) |
| 37 | if ctx.Err() != nil { |
| 38 | t.Fatal("Shutdown ran out of time instead of aborting the wake") |
| 39 | } |
| 40 | |
| 41 | // Every lease this agent took is given back by the time Shutdown |
| 42 | // returns: the first wake's through its replica's Close, the |
| 43 | // re-wake's through Release, and never over a start job still queued. |
| 44 | acq, _, _ := b.counts() |
| 45 | if got := b.releaseCount(); got != acq { |
| 46 | t.Fatalf("lease releases = %d after Shutdown, want %d (one per acquire)", got, acq) |
| 47 | } |
| 48 | b.mu.Lock() |
| 49 | queuedAt, queuedNow, stops := slices.Clone(b.queuedAtRelease), b.queuedJobs, b.legacyStops |
| 50 | b.mu.Unlock() |
| 51 | if stops == 0 || queuedNow != 0 { |
| 52 | t.Fatalf("the aborted start's queued job was never stopped (stops %d, queued %d)", stops, queuedNow) |
| 53 | } |
| 54 | for _, q := range queuedAt { |
| 55 | if q != 0 { |
| 56 | t.Fatalf("a lease was released with %d start job(s) still queued: %v", q, queuedAt) |
| 57 | } |
| 58 | } |
| 59 | for _, err := range b.releaseCtxErrors() { |
| 60 | if err != nil { |
| 61 | t.Fatalf("a lease was released under a dead context (%v)", err) |
| 62 | } |
| 63 | } |
| 64 | if n := a.entryCount(); n != 0 { |
| 65 | t.Fatalf("Shutdown left %d entr(ies) behind", n) |
| 66 | } |
| 67 | select { |
| 68 | case err := <-reqErr: |
| 69 | if err == nil { |
| 70 | t.Fatal("the request was served by a wake Shutdown aborted") |
| 71 | } |
| 72 | case <-time.After(5 * time.Second): |
| 73 | t.Fatal("the queued request never returned") |
| 74 | } |
| 75 | } |
| 76 | |
| 77 | // arrangeQueuedRewake is #292's arrangement: host awake, its unit stopped |
| 78 | // by systemd, and a request's re-wake inside a start that systemd has |
| 79 | // queued behind the edge restart. It returns the request's outcome. |
| 80 | func arrangeQueuedRewake(t *testing.T, host string) (*Service, *fakeBackend, <-chan error) { |
| 81 | t.Helper() |
| 82 | a, b, _, _ := testActivator(t, time.Hour) |
| 83 | arrangeAwake(t, a, testRoute(host)) |
| 84 | |
| 85 | // systemd stops the bound unit, well before the agent's SIGTERM. |
| 86 | b.lastProc().kill() |
| 87 | queued := make(chan struct{}) |
| 88 | b.mu.Lock() |
| 89 | b.startQueued = queued |
| 90 | b.mu.Unlock() |
| 91 | t.Cleanup(func() { close(queued) }) |
| 92 | |
| 93 | reqErr := make(chan error, 1) |
| 94 | go func() { |
| 95 | release, err := a.beginRequest(context.Background(), testRoute(host)) |
| 96 | if err == nil { |
| 97 | release() |
| 98 | } |
| 99 | reqErr <- err |
| 100 | }() |
| 101 | waitFor(t, "the re-wake to reach its queued start", func() bool { return b.startCount() == 2 }) |
| 102 | if acq, _, _ := b.counts(); acq != 2 { |
| 103 | t.Fatalf("acquires = %d, want 2 (the first wake and the re-wake)", acq) |
| 104 | } |
| 105 | return a, b, reqErr |
| 106 | } |
| 107 | |
| 108 | // P1's other half: an aborted legacy start whose unit cannot be proven |
| 109 | // stopped KEEPS its lease. A lease left to its TTL is a 15-minute stall; a |
| 110 | // lease given back over a queued start job is two writers. |
| 111 | func TestAnAbortedStartNotProvenStoppedKeepsItsLease(t *testing.T) { |
| 112 | t.Parallel() |
| 113 | a, b, _ := arrangeQueuedRewake(t, "unproven.example.com") |
| 114 | b.mu.Lock() |
| 115 | b.legacyStopErr = errors.New("stop carlos-instance@unproven: instance control socket: connection refused") |
| 116 | b.mu.Unlock() |
| 117 | |
| 118 | // An unproven start keeps Shutdown polling until its budget ends, so |
| 119 | // the budget is all this test waits: half a second is five of its polls. |
| 120 | ctx, cancel := context.WithTimeout(context.Background(), 500*time.Millisecond) |
| 121 | defer cancel() |
| 122 | a.Shutdown(ctx) |
| 123 | |
| 124 | acq, _, _ := b.counts() |
| 125 | if got := b.releaseCount(); got != acq-1 { |
| 126 | t.Fatalf("lease releases = %d, want %d: the first wake's, and NOT the aborted start's", got, acq-1) |
| 127 | } |
| 128 | b.mu.Lock() |
| 129 | stops := b.legacyStops |
| 130 | b.mu.Unlock() |
| 131 | if stops == 0 { |
| 132 | t.Fatal("the aborted start's unit was never asked to stop") |
| 133 | } |
| 134 | a.mu.Lock() |
| 135 | _, retained := a.unprovenWakes["unproven.example.com"] |
| 136 | a.mu.Unlock() |
| 137 | if !retained { |
| 138 | t.Fatal("the unproven start was not retained with its lease") |
| 139 | } |
| 140 | } |
| 141 | |
| 142 | // P2: a wake that ignores its cancellation holds Shutdown's join, and an |
| 143 | // entry whose stop was left pending must still be finished meanwhile: |
| 144 | // its process exits, and its lease goes back then, not once every wake |
| 145 | // has joined. |
| 146 | func TestShutdownFinishesPendingStopsWhileJoiningWakes(t *testing.T) { |
| 147 | t.Parallel() |
| 148 | a, b, _, _ := testActivator(t, time.Hour) |
| 149 | stuckHost, wakingHost := "stuck.example.com", "waking.example.com" |
| 150 | b.procStuck = true |
| 151 | arrangeAwake(t, a, testRoute(stuckHost)) |
| 152 | stuck := b.lastProc() |
| 153 | stuckRep := b.lastRep() |
| 154 | |
| 155 | b.mu.Lock() |
| 156 | b.procStuck = false |
| 157 | gate := make(chan struct{}) |
| 158 | b.startGate = gate |
| 159 | b.mu.Unlock() |
| 160 | go func() { |
| 161 | if release, err := a.beginRequest(context.Background(), testRoute(wakingHost)); err == nil { |
| 162 | release() |
| 163 | } |
| 164 | }() |
| 165 | waitFor(t, "the wake to reach Start", func() bool { return b.startCount() == 2 }) |
| 166 | |
| 167 | ctx, cancel := context.WithTimeout(context.Background(), 20*time.Second) |
| 168 | defer cancel() |
| 169 | done := make(chan struct{}) |
| 170 | go func() { a.Shutdown(ctx); close(done) }() |
| 171 | waitFor(t, "the stuck stop to be left pending", func() bool { |
| 172 | a.mu.Lock() |
| 173 | defer a.mu.Unlock() |
| 174 | e := a.entries[stuckHost] |
| 175 | return e != nil && e.pendingStop |
| 176 | }) |
| 177 | stuck.exit() |
| 178 | waitFor(t, "the pending stop's lease to go back while a wake is still joining", stuckRep.isClosed) |
| 179 | select { |
| 180 | case <-done: |
| 181 | t.Fatal("Shutdown returned while a wake was still spawning") |
| 182 | default: |
| 183 | } |
| 184 | close(gate) |
| 185 | <-done |
| 186 | } |
| 187 | |
| 188 | // P3: a failed release is an obligation, not a forgotten handle. A wake |
| 189 | // that fails gives its lease back, the store refuses the DELETE, and |
| 190 | // Shutdown retries it (conditionally) inside its own budget. |
| 191 | func TestShutdownRetriesAFailedLeaseRelease(t *testing.T) { |
| 192 | t.Parallel() |
| 193 | a, b, _, _ := testActivator(t, time.Hour) |
| 194 | b.startErr = errors.New("start failed") |
| 195 | b.releaseErrs = []error{errors.New("delete lease: context deadline exceeded")} |
| 196 | if _, err := a.beginRequest(context.Background(), testRoute("refused.example.com")); err == nil { |
| 197 | t.Fatal("the wake succeeded") |
| 198 | } |
| 199 | if got := b.releaseCount(); got != 0 { |
| 200 | t.Fatalf("lease releases = %d before Shutdown, want 0 (the DELETE failed)", got) |
| 201 | } |
| 202 | |
| 203 | ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) |
| 204 | defer cancel() |
| 205 | a.Shutdown(ctx) |
| 206 | if ctx.Err() != nil { |
| 207 | t.Fatal("Shutdown ran out of time") |
| 208 | } |
| 209 | b.mu.Lock() |
| 210 | retries := b.retries |
| 211 | b.mu.Unlock() |
| 212 | if got := b.releaseCount(); got != 1 || retries == 0 { |
| 213 | t.Fatalf("lease releases = %d after %d retries, want the failed release retried and landed", got, retries) |
| 214 | } |
| 215 | } |
| 216 | |
| 217 | // P3's other half: a release still unresolved when Shutdown's budget ends |
| 218 | // is logged by host, not dropped silently. |
| 219 | func TestShutdownLogsALeaseReleaseItCouldNotResolve(t *testing.T) { |
| 220 | logs := lockedLog(t) |
| 221 | a, b, _, _ := testActivator(t, time.Hour) |
| 222 | b.startErr = errors.New("start failed") |
| 223 | b.releaseErrs = []error{errors.New("delete lease: timeout")} |
| 224 | for i := 0; i < 1000; i++ { |
| 225 | b.retryErrs = append(b.retryErrs, errors.New("delete lease: timeout")) |
| 226 | } |
| 227 | if _, err := a.beginRequest(context.Background(), testRoute("dark.example.com")); err == nil { |
| 228 | t.Fatal("the wake succeeded") |
| 229 | } |
| 230 | ctx, cancel := context.WithTimeout(context.Background(), 500*time.Millisecond) |
| 231 | defer cancel() |
| 232 | a.Shutdown(ctx) |
| 233 | if got := b.releaseCount(); got != 0 { |
| 234 | t.Fatalf("lease releases = %d, want 0", got) |
| 235 | } |
| 236 | if out := logs.String(); !strings.Contains(out, "unresolved") || !strings.Contains(out, "dark.example.com") { |
| 237 | t.Fatalf("no unresolved-release line naming the host at exit; log:\n%s", out) |
| 238 | } |
| 239 | } |
| 240 | |
| 241 | // lockedBuf is a log sink safe against the activator's own goroutines. |
| 242 | type lockedBuf struct { |
| 243 | mu sync.Mutex |
| 244 | buf strings.Builder |
| 245 | } |
| 246 | |
| 247 | func (l *lockedBuf) Write(p []byte) (int, error) { |
| 248 | l.mu.Lock() |
| 249 | defer l.mu.Unlock() |
| 250 | return l.buf.Write(p) |
| 251 | } |
| 252 | |
| 253 | func (l *lockedBuf) String() string { |
| 254 | l.mu.Lock() |
| 255 | defer l.mu.Unlock() |
| 256 | return l.buf.String() |
| 257 | } |
| 258 | |
| 259 | func lockedLog(t *testing.T) *lockedBuf { |
| 260 | t.Helper() |
| 261 | l := &lockedBuf{} |
| 262 | flags := log.Flags() |
| 263 | log.SetOutput(l) |
| 264 | log.SetFlags(0) |
| 265 | t.Cleanup(func() { |
| 266 | log.SetOutput(os.Stderr) |
| 267 | log.SetFlags(flags) |
| 268 | }) |
| 269 | return l |
| 270 | } |
| 271 | |
| 272 | // Once Shutdown has begun, nothing wakes. A request queued on a stop must |
| 273 | // not wake the host afresh when that stop finishes after Shutdown began: |
| 274 | // the wake would take a lease once Shutdown had stopped looking. Startup |
| 275 | // is closed, as it is on a running agent, and the request is already past |
| 276 | // the startup gate (queued on a Bounce's stop) when the shutdown begins. |
| 277 | func TestNoWakeOnceShutdownHasBegun(t *testing.T) { |
| 278 | t.Parallel() |
| 279 | a, b, _, _ := testActivator(t, time.Hour) |
| 280 | started := make(chan struct{}) |
| 281 | close(started) |
| 282 | a.Startup = started |
| 283 | host := "queued.example.com" |
| 284 | arrangeAwake(t, a, testRoute(host)) |
| 285 | stopGate := make(chan struct{}) |
| 286 | b.lastProc().setStopGate(stopGate) |
| 287 | if !a.Bounce(host) { |
| 288 | t.Fatal("Bounce(awake host) = false") |
| 289 | } |
| 290 | waitFor(t, "the Bounce's stop", func() bool { return b.lastProc().stopEntered() == 1 }) |
| 291 | |
| 292 | reqErr := make(chan error, 1) |
| 293 | go func() { |
| 294 | release, err := a.beginRequest(context.Background(), testRoute(host)) |
| 295 | if err == nil { |
| 296 | release() |
| 297 | } |
| 298 | reqErr <- err |
| 299 | }() |
| 300 | // The request is queued on the stop before the shutdown begins. |
| 301 | time.Sleep(50 * time.Millisecond) |
| 302 | |
| 303 | done := make(chan struct{}) |
| 304 | go func() { |
| 305 | ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) |
| 306 | defer cancel() |
| 307 | a.Shutdown(ctx) |
| 308 | close(done) |
| 309 | }() |
| 310 | waitFor(t, "Shutdown to begin", func() bool { |
| 311 | a.mu.Lock() |
| 312 | defer a.mu.Unlock() |
| 313 | return a.shuttingDown |
| 314 | }) |
| 315 | close(stopGate) |
| 316 | <-done |
| 317 | |
| 318 | select { |
| 319 | case err := <-reqErr: |
| 320 | if err == nil { |
| 321 | t.Fatal("a request woke the host after Shutdown had begun") |
| 322 | } |
| 323 | case <-time.After(5 * time.Second): |
| 324 | t.Fatal("the queued request never returned") |
| 325 | } |
| 326 | if acq, _, starts := b.counts(); acq != 1 || starts != 1 { |
| 327 | t.Fatalf("acquires, starts = %d, %d; want 1, 1 (nothing woken after Shutdown began)", acq, starts) |
| 328 | } |
| 329 | time.Sleep(50 * time.Millisecond) |
| 330 | if n := a.entryCount(); n != 0 { |
| 331 | t.Fatalf("%d entr(ies) live after Shutdown", n) |
| 332 | } |
| 333 | } |
| 334 | |
| 335 | // An exit seen once Shutdown has begun is the shutdown's, not the |
| 336 | // build's: neither the sweep nor a request reads it as unexpected or |
| 337 | // recycles it. Shutdown's own stop takes the entry down. |
| 338 | func TestAnExitAfterShutdownBeganIsNotUnexpected(t *testing.T) { |
| 339 | a, b, _, _ := testActivator(t, time.Hour) |
| 340 | host := "exit.example.com" |
| 341 | arrangeAwake(t, a, testRoute(host)) |
| 342 | b.lastProc().kill() |
| 343 | // The moment between Shutdown announcing itself and taking its |
| 344 | // snapshot of the entries. |
| 345 | a.mu.Lock() |
| 346 | a.shuttingDown = true |
| 347 | a.mu.Unlock() |
| 348 | |
| 349 | a.sweepOnce() |
| 350 | if _, err := a.beginRequest(context.Background(), testRoute(host)); err == nil { |
| 351 | t.Fatal("a request was served once Shutdown had begun") |
| 352 | } |
| 353 | a.mu.Lock() |
| 354 | e := a.entries[host] |
| 355 | state, unexpected := actAwake, false |
| 356 | if e != nil { |
| 357 | state, unexpected = e.state, e.unexpectedExit |
| 358 | } |
| 359 | a.mu.Unlock() |
| 360 | if e == nil || state != actAwake { |
| 361 | t.Fatalf("the exit was recycled after Shutdown began (entry %v, state %v)", e != nil, state) |
| 362 | } |
| 363 | if unexpected { |
| 364 | t.Fatal("an exit after Shutdown began was read as unexpected") |
| 365 | } |
| 366 | if acq, _, _ := b.counts(); acq != 1 { |
| 367 | t.Fatalf("acquires = %d, want 1", acq) |
| 368 | } |
| 369 | |
| 370 | ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) |
| 371 | defer cancel() |
| 372 | a.Shutdown(ctx) |
| 373 | if n := a.entryCount(); n != 0 { |
| 374 | t.Fatalf("Shutdown left %d entr(ies) behind", n) |
| 375 | } |
| 376 | if got := b.releaseCount(); got != 1 { |
| 377 | t.Fatalf("lease releases = %d, want 1", got) |
| 378 | } |
| 379 | } |
| 380 | |
| 381 | // Round 2 P2: release obligations expire. Under a persistent DELETE refusal |
| 382 | // with acquisition still allowed, every failed wake adds one; once their |
| 383 | // records pass their own expiry the retries retire them (logged) instead |
| 384 | // of running forever. |
| 385 | func TestOwedReleasesAreRetiredOnceTheirRecordsExpire(t *testing.T) { |
| 386 | logs := lockedLog(t) |
| 387 | a, b, _, _ := testActivator(t, time.Hour) |
| 388 | b.startErr = errors.New("start failed") |
| 389 | hosts := []string{"one.example.com", "two.example.com", "three.example.com"} |
| 390 | for range hosts { |
| 391 | b.releaseErrs = append(b.releaseErrs, errors.New("delete lease: AccessDenied")) |
| 392 | } |
| 393 | for i := 0; i < 1000; i++ { |
| 394 | b.retryErrs = append(b.retryErrs, errors.New("delete lease: AccessDenied")) |
| 395 | } |
| 396 | for _, h := range hosts { |
| 397 | if _, err := a.beginRequest(context.Background(), testRoute(h)); err == nil { |
| 398 | t.Fatalf("%s: the wake succeeded", h) |
| 399 | } |
| 400 | } |
| 401 | owed := func() int { |
| 402 | a.mu.Lock() |
| 403 | defer a.mu.Unlock() |
| 404 | a.finishPendingStops() |
| 405 | return len(a.owedReleases) |
| 406 | } |
| 407 | time.Sleep(50 * time.Millisecond) |
| 408 | if n := owed(); n != len(hosts) { |
| 409 | t.Fatalf("owed releases = %d before expiry, want %d", n, len(hosts)) |
| 410 | } |
| 411 | b.mu.Lock() |
| 412 | b.leaseLapsed = true |
| 413 | b.mu.Unlock() |
| 414 | waitFor(t, "the expired obligations to be retired", func() bool { return owed() == 0 }) |
| 415 | out := logs.String() |
| 416 | if !strings.Contains(out, "retired") { |
| 417 | t.Fatalf("no retirement line; log:\n%s", out) |
| 418 | } |
| 419 | if strings.Contains(out, "given back on retry") || b.releaseCount() != 0 { |
| 420 | t.Fatalf("an expired, never-deleted lease was reported as given back; log:\n%s", out) |
| 421 | } |
| 422 | } |
| 423 | |
| 424 | // Astra, lower priority: the legacy proof is bounded by Shutdown's budget |
| 425 | // as well as its own 30 s, whichever ends first, so no proof outlives |
| 426 | // Shutdown. Unproven, the lease is still kept. |
| 427 | func TestTheLegacyProofEndsWithShutdownsBudget(t *testing.T) { |
| 428 | t.Parallel() |
| 429 | a, b, _ := arrangeQueuedRewake(t, "slowproof.example.com") |
| 430 | b.mu.Lock() |
| 431 | b.legacyBlock = true |
| 432 | b.mu.Unlock() |
| 433 | |
| 434 | ctx, cancel := context.WithTimeout(context.Background(), 300*time.Millisecond) |
| 435 | defer cancel() |
| 436 | a.Shutdown(ctx) |
| 437 | waitFor(t, "the proof to end with Shutdown's budget", func() bool { |
| 438 | b.mu.Lock() |
| 439 | defer b.mu.Unlock() |
| 440 | return b.legacyEnded > 0 |
| 441 | }) |
| 442 | acq, _, _ := b.counts() |
| 443 | if got := b.releaseCount(); got != acq-1 { |
| 444 | t.Fatalf("lease releases = %d, want %d: an unproven start keeps its lease", got, acq-1) |
| 445 | } |
| 446 | } |
| 447 | |
| 448 | // Astra round 3 P2: a proof already running when Shutdown begins (here a |
| 449 | // failed start's, from before the shutdown, under its own 30 s budget) |
| 450 | // ends when Shutdown's budget does. Cut short, it is unproven, and the |
| 451 | // lease is kept. |
| 452 | func TestAProofRunningBeforeShutdownEndsWithItsBudget(t *testing.T) { |
| 453 | t.Parallel() |
| 454 | a, b, _, _ := testActivator(t, time.Hour) |
| 455 | b.mu.Lock() |
| 456 | b.startLegacyFail, b.legacyBlock = true, true |
| 457 | b.mu.Unlock() |
| 458 | go func() { |
| 459 | if release, err := a.beginRequest(context.Background(), testRoute("early.example.com")); err == nil { |
| 460 | release() |
| 461 | } |
| 462 | }() |
| 463 | waitFor(t, "the failed start's proof to begin", func() bool { |
| 464 | b.mu.Lock() |
| 465 | defer b.mu.Unlock() |
| 466 | return b.legacyStops == 1 |
| 467 | }) |
| 468 | ctx, cancel := context.WithTimeout(context.Background(), 300*time.Millisecond) |
| 469 | defer cancel() |
| 470 | a.Shutdown(ctx) |
| 471 | waitFor(t, "the proof to end with Shutdown's budget", func() bool { |
| 472 | b.mu.Lock() |
| 473 | defer b.mu.Unlock() |
| 474 | return b.legacyEnded > 0 |
| 475 | }) |
| 476 | if got := b.releaseCount(); got != 0 { |
| 477 | t.Fatalf("lease releases = %d, want 0: a proof cut short keeps the lease", got) |
| 478 | } |
| 479 | } |
| 480 | |
amadan