| 1 | package calls |
| 2 | |
| 3 | import ( |
| 4 | "context" |
| 5 | "fmt" |
| 6 | "log/slog" |
| 7 | "net/http" |
| 8 | "path/filepath" |
| 9 | "runtime" |
| 10 | "strings" |
| 11 | "sync" |
| 12 | "sync/atomic" |
| 13 | "testing" |
| 14 | "time" |
| 15 | |
| 16 | "amadan.net/rastrillo/rastrillo/db" |
| 17 | ) |
| 18 | |
| 19 | // stuckHandler is a slog handler whose every write blocks until release |
| 20 | // is closed: a log sink that has stalled, as a full pipe does. It |
| 21 | // remembers what it was finally allowed to write. |
| 22 | type stuckHandler struct { |
| 23 | release chan struct{} |
| 24 | mu *sync.Mutex |
| 25 | msgs *[]string |
| 26 | } |
| 27 | |
| 28 | func (h stuckHandler) Enabled(context.Context, slog.Level) bool { return true } |
| 29 | func (h stuckHandler) Handle(_ context.Context, r slog.Record) error { |
| 30 | <-h.release |
| 31 | h.mu.Lock() |
| 32 | *h.msgs = append(*h.msgs, r.Message) |
| 33 | h.mu.Unlock() |
| 34 | return nil |
| 35 | } |
| 36 | func (h stuckHandler) WithAttrs([]slog.Attr) slog.Handler { return h } |
| 37 | func (h stuckHandler) WithGroup(string) slog.Handler { return h } |
| 38 | |
| 39 | // funcSender adapts a function to mail.Sender. |
| 40 | type funcSender func(ctx context.Context, to string) error |
| 41 | |
| 42 | func (f funcSender) Send(ctx context.Context, to, _, _ string) error { return f(ctx, to) } |
| 43 | |
| 44 | func everyone(string) bool { return true } |
| 45 | |
| 46 | // TestMailQueueSendNeverBlocksWhenFull: Send is the request path, so it |
| 47 | // may not block or do I/O even when the queue is full — not even to log |
| 48 | // the drop (Astra on oficina/slides #20, round 2, P1: a "queue full" log |
| 49 | // line on a stalled sink held the request, and saturation is |
| 50 | // admission-dependent). The worker is stuck on its first link and the |
| 51 | // log sink is stuck too; twice the queue's depth of Sends must still |
| 52 | // return at once, and the drops are logged by the worker afterwards. |
| 53 | func TestMailQueueSendNeverBlocksWhenFull(t *testing.T) { |
| 54 | release := make(chan struct{}) |
| 55 | var once sync.Once |
| 56 | free := func() { once.Do(func() { close(release) }) } |
| 57 | stuck := funcSender(func(ctx context.Context, _ string) error { |
| 58 | select { |
| 59 | case <-release: |
| 60 | case <-ctx.Done(): |
| 61 | } |
| 62 | return nil |
| 63 | }) |
| 64 | var mu sync.Mutex |
| 65 | var msgs []string |
| 66 | q := newMailQueue(stuck, everyone, nil, slog.New(stuckHandler{release, &mu, &msgs})) |
| 67 | t.Cleanup(func() { free(); q.close() }) |
| 68 | |
| 69 | done := make(chan struct{}) |
| 70 | go func() { |
| 71 | for i := 0; i < 2*mailQueueDepth; i++ { |
| 72 | _ = q.Send(context.Background(), fmt.Sprintf("p%d@example.test", i), "s", "b") |
| 73 | } |
| 74 | close(done) |
| 75 | }() |
| 76 | select { |
| 77 | case <-done: |
| 78 | case <-time.After(2 * time.Second): |
| 79 | free() |
| 80 | <-done |
| 81 | t.Fatal("Send blocked with the queue full: the request path waited on the queue or the log") |
| 82 | } |
| 83 | // The drops are the worker's to log, through the pump, once the |
| 84 | // sink is free. |
| 85 | free() |
| 86 | q.close() |
| 87 | deadline := time.Now().Add(2 * time.Second) |
| 88 | for time.Now().Before(deadline) { |
| 89 | mu.Lock() |
| 90 | for _, m := range msgs { |
| 91 | if strings.Contains(m, "links dropped") { |
| 92 | mu.Unlock() |
| 93 | return |
| 94 | } |
| 95 | } |
| 96 | mu.Unlock() |
| 97 | time.Sleep(5 * time.Millisecond) |
| 98 | } |
| 99 | t.Fatalf("no drop was logged with twice the queue's depth sent; the log has %q", msgs) |
| 100 | } |
| 101 | |
| 102 | // TestMailQueueQueuesEveryAddress: the queue's fill level must not |
| 103 | // depend on admission, so Send queues a refused address's link exactly |
| 104 | // as it queues a permitted one; only the worker asks. |
| 105 | func TestMailQueueQueuesEveryAddress(t *testing.T) { |
| 106 | release := make(chan struct{}) |
| 107 | stuck := funcSender(func(ctx context.Context, _ string) error { |
| 108 | select { |
| 109 | case <-release: |
| 110 | case <-ctx.Done(): |
| 111 | } |
| 112 | return nil |
| 113 | }) |
| 114 | var asked sync.Map |
| 115 | admits := func(to string) bool { asked.Store(to, true); return to == "first@example.test" } |
| 116 | q := newMailQueue(stuck, admits, nil, slog.New(slog.DiscardHandler)) |
| 117 | t.Cleanup(func() { close(release); q.close() }) |
| 118 | _ = q.Send(context.Background(), "first@example.test", "s", "b") |
| 119 | deadline := time.Now().Add(2 * time.Second) |
| 120 | for _, ok := asked.Load("first@example.test"); !ok && time.Now().Before(deadline); _, ok = asked.Load("first@example.test") { |
| 121 | time.Sleep(5 * time.Millisecond) |
| 122 | } |
| 123 | for i := 0; i < 5; i++ { |
| 124 | _ = q.Send(context.Background(), fmt.Sprintf("refused%d@example.test", i), "s", "b") |
| 125 | } |
| 126 | if got := len(q.jobs); got != 5 { |
| 127 | t.Fatalf("queued %d refused links, want all 5: fill level must not depend on admission", got) |
| 128 | } |
| 129 | } |
| 130 | |
| 131 | // TestMailQueueSurvivesAPanic: a panic in the mailer is that message's |
| 132 | // failure; the worker recovers, logs, and sends the next one (Astra, |
| 133 | // round 2, P2). |
| 134 | func TestMailQueueSurvivesAPanic(t *testing.T) { |
| 135 | var mu sync.Mutex |
| 136 | var sent []string |
| 137 | calls := 0 |
| 138 | s := funcSender(func(_ context.Context, to string) error { |
| 139 | mu.Lock() |
| 140 | defer mu.Unlock() |
| 141 | calls++ |
| 142 | if calls == 1 { |
| 143 | panic("mailer exploded") |
| 144 | } |
| 145 | sent = append(sent, to) |
| 146 | return nil |
| 147 | }) |
| 148 | q := newMailQueue(s, everyone, nil, slog.New(slog.DiscardHandler)) |
| 149 | t.Cleanup(q.close) |
| 150 | _ = q.Send(context.Background(), "first@example.test", "s", "b") |
| 151 | _ = q.Send(context.Background(), "second@example.test", "s", "b") |
| 152 | q.wait() |
| 153 | mu.Lock() |
| 154 | defer mu.Unlock() |
| 155 | if len(sent) != 1 || sent[0] != "second@example.test" { |
| 156 | t.Fatalf("sent = %v, want the second link after the first panicked", sent) |
| 157 | } |
| 158 | } |
| 159 | |
| 160 | // TestMailQueueCloseIsBoundedAndStopsTheWorker: close drains within its |
| 161 | // deadline, then cancels the send in flight, abandons the rest, and the |
| 162 | // worker is gone — no goroutine outlives close (Astra, round 2, P2). |
| 163 | func TestMailQueueCloseIsBoundedAndStopsTheWorker(t *testing.T) { |
| 164 | baseline := runtime.NumGoroutine() |
| 165 | honours := funcSender(func(ctx context.Context, _ string) error { |
| 166 | <-ctx.Done() // a relay that never answers, but obeys cancellation |
| 167 | return ctx.Err() |
| 168 | }) |
| 169 | q := newMailQueue(honours, everyone, nil, slog.New(slog.DiscardHandler)) |
| 170 | q.drainTimeout = 50 * time.Millisecond |
| 171 | for i := 0; i < 3; i++ { |
| 172 | _ = q.Send(context.Background(), fmt.Sprintf("p%d@example.test", i), "s", "b") |
| 173 | } |
| 174 | start := time.Now() |
| 175 | q.close() |
| 176 | if took := time.Since(start); took > 2*time.Second { |
| 177 | t.Fatalf("close took %v, want about its 50ms deadline", took) |
| 178 | } |
| 179 | select { |
| 180 | case <-q.done: |
| 181 | default: |
| 182 | t.Fatal("the worker was still running after close") |
| 183 | } |
| 184 | deadline := time.Now().Add(time.Second) |
| 185 | for runtime.NumGoroutine() > baseline && time.Now().Before(deadline) { |
| 186 | time.Sleep(5 * time.Millisecond) |
| 187 | } |
| 188 | if n := runtime.NumGoroutine(); n > baseline { |
| 189 | t.Fatalf("%d goroutines after close, %d before: the queue leaked", n, baseline) |
| 190 | } |
| 191 | } |
| 192 | |
| 193 | // TestMailQueueCloseJoinsAnInProgressClose: close can be reached twice |
| 194 | // (a TestHandle's stop and a cleanup, say). The second close must wait |
| 195 | // for the first one's drain, not return because the queue is already |
| 196 | // marked closed, or a caller about to close the database or exit would |
| 197 | // leave an acknowledged link still at the relay (Astra on oficina/meet |
| 198 | // #25). |
| 199 | func TestMailQueueCloseJoinsAnInProgressClose(t *testing.T) { |
| 200 | release, sending := make(chan struct{}), make(chan struct{}) |
| 201 | var sent atomic.Bool |
| 202 | slow := funcSender(func(context.Context, string) error { |
| 203 | close(sending) |
| 204 | <-release |
| 205 | sent.Store(true) |
| 206 | return nil |
| 207 | }) |
| 208 | q := newMailQueue(slow, everyone, nil, slog.New(slog.DiscardHandler)) |
| 209 | _ = q.Send(context.Background(), "paul@example.test", "s", "b") |
| 210 | <-sending |
| 211 | |
| 212 | first := make(chan struct{}) |
| 213 | go func() { q.close(); close(first) }() |
| 214 | for { |
| 215 | q.mu.RLock() |
| 216 | closed := q.closed |
| 217 | q.mu.RUnlock() |
| 218 | if closed { |
| 219 | break |
| 220 | } |
| 221 | time.Sleep(time.Millisecond) |
| 222 | } |
| 223 | second := make(chan struct{}) |
| 224 | go func() { q.close(); close(second) }() |
| 225 | select { |
| 226 | case <-second: |
| 227 | t.Fatal("a second close returned while the first was still draining") |
| 228 | case <-time.After(100 * time.Millisecond): |
| 229 | } |
| 230 | close(release) |
| 231 | for _, c := range []chan struct{}{first, second} { |
| 232 | select { |
| 233 | case <-c: |
| 234 | case <-time.After(5 * time.Second): |
| 235 | t.Fatal("close did not return after the send finished") |
| 236 | } |
| 237 | } |
| 238 | if !sent.Load() { |
| 239 | t.Fatal("the queued link was not sent before close returned") |
| 240 | } |
| 241 | } |
| 242 | |
| 243 | // mailWorkers counts goroutines running a sign-in mail queue's worker |
| 244 | // or log pump — the targeted leak check (goleak's idea, without the |
| 245 | // dependency) TestMain runs after the package's tests. |
| 246 | func mailWorkers() int { |
| 247 | buf := make([]byte, 1<<22) |
| 248 | stacks := string(buf[:runtime.Stack(buf, true)]) |
| 249 | return strings.Count(stacks, "(*mailQueue).run(") + strings.Count(stacks, "(*mailQueue).pump(") |
| 250 | } |
| 251 | |
| 252 | // TestMailQueueCloseIsBoundedWithAStalledLogger: close reports through |
| 253 | // nothing that can block, and never waits on the log pump. With the log |
| 254 | // sink stalled — every write hangs — and a relay that never answers but |
| 255 | // honours cancellation, and WHILE THE SINK IS STILL STALLED: |
| 256 | // |
| 257 | // - close returns within its bound; |
| 258 | // - the mail worker has exited; |
| 259 | // - at most the one log pump remains, blocked in its write. |
| 260 | // |
| 261 | // A write blocked inside the logger cannot be interrupted from Go; it |
| 262 | // can only finish or die with the process, and shutdown deliberately |
| 263 | // does not wait for it. So only once the sink is released must the pump |
| 264 | // exit and the goroutine count return to its baseline (Astra on #20, |
| 265 | // rounds 3 and 4). The test fails if close waited on the pump, or if |
| 266 | // the pump could hold the worker. |
| 267 | func TestMailQueueCloseIsBoundedWithAStalledLogger(t *testing.T) { |
| 268 | waitFor := func(cond func() bool) bool { |
| 269 | deadline := time.Now().Add(2 * time.Second) |
| 270 | for !cond() && time.Now().Before(deadline) { |
| 271 | time.Sleep(5 * time.Millisecond) |
| 272 | } |
| 273 | return cond() |
| 274 | } |
| 275 | // Baselines, not zero: another test's queue may still be shutting |
| 276 | // down beside this one. |
| 277 | baseline, workers := runtime.NumGoroutine(), mailWorkers() |
| 278 | release := make(chan struct{}) |
| 279 | var once sync.Once |
| 280 | free := func() { once.Do(func() { close(release) }) } |
| 281 | t.Cleanup(free) |
| 282 | var mu sync.Mutex |
| 283 | var msgs []string |
| 284 | honours := funcSender(func(ctx context.Context, _ string) error { |
| 285 | <-ctx.Done() |
| 286 | return ctx.Err() |
| 287 | }) |
| 288 | q := newMailQueue(honours, everyone, nil, slog.New(stuckHandler{release, &mu, &msgs})) |
| 289 | q.drainTimeout = 50 * time.Millisecond |
| 290 | for i := 0; i < 2*mailQueueDepth; i++ { // drops too, so there is plenty to log |
| 291 | _ = q.Send(context.Background(), fmt.Sprintf("p%d@example.test", i), "s", "b") |
| 292 | } |
| 293 | closed := make(chan struct{}) |
| 294 | go func() { q.close(); close(closed) }() |
| 295 | select { |
| 296 | case <-closed: |
| 297 | case <-time.After(2 * time.Second): |
| 298 | free() |
| 299 | <-closed |
| 300 | t.Fatal("close hung on a stalled log sink") |
| 301 | } |
| 302 | |
| 303 | // The sink is still stalled. |
| 304 | select { |
| 305 | case <-q.done: |
| 306 | default: |
| 307 | t.Fatal("the worker was still running after close, held by the stalled log sink") |
| 308 | } |
| 309 | if !waitFor(func() bool { return runtime.NumGoroutine() <= baseline+1 }) { |
| 310 | t.Fatalf("%d goroutines with the sink stalled, %d before: more than the one blocked log pump remains", runtime.NumGoroutine(), baseline) |
| 311 | } |
| 312 | if n := mailWorkers(); n > workers+1 { |
| 313 | t.Fatalf("%d mail queue goroutines with the sink stalled, %d before: want at most the log pump more", n, workers) |
| 314 | } |
| 315 | |
| 316 | // Released, the pump finishes its write and exits. |
| 317 | free() |
| 318 | if !waitFor(func() bool { return mailWorkers() <= workers && runtime.NumGoroutine() <= baseline }) { |
| 319 | t.Fatalf("after release: %d mail queue goroutines, %d goroutines against %d before", mailWorkers(), runtime.NumGoroutine(), baseline) |
| 320 | } |
| 321 | } |
| 322 | |
| 323 | // buildForTest is build on the test's context, with the sign-in mail |
| 324 | // queue closed in cleanup: the context ending no longer closes it (see |
| 325 | // build), so whoever builds an app closes its queue. |
| 326 | func buildForTest(t *testing.T, d *db.DB, cfg Config) (*http.ServeMux, *app, error) { |
| 327 | t.Helper() |
| 328 | mux, a, err := build(t.Context(), d, cfg) |
| 329 | if err == nil { |
| 330 | t.Cleanup(a.signinMail.close) |
| 331 | } |
| 332 | return mux, a, err |
| 333 | } |
| 334 | |
| 335 | // TestShutdownStopsTheMailWorker: the app's context ending (SIGTERM) |
| 336 | // stops streams and background work but NOT mail intake, because |
| 337 | // Server.Shutdown is still letting accepted requests finish and their |
| 338 | // links must still go out (Astra on #25, round 2). The queue takes links |
| 339 | // until its owner closes it (Runtime.Close, or a TestHandle's stop), and |
| 340 | // that close stops the worker, so nothing that closes its app leaves |
| 341 | // one running. |
| 342 | func TestShutdownStopsTheMailWorker(t *testing.T) { |
| 343 | logger := slog.New(slog.DiscardHandler) |
| 344 | d, err := db.Open(filepath.Join(t.TempDir(), "calls.db"), logger) |
| 345 | if err != nil { |
| 346 | t.Fatal(err) |
| 347 | } |
| 348 | t.Cleanup(func() { d.Close() }) |
| 349 | ctx, cancel := context.WithCancel(context.Background()) |
| 350 | _, a, err := build(ctx, d, Config{Env: EnvDevelopment, Origin: "http://app.test", Logger: logger}) |
| 351 | if err != nil { |
| 352 | t.Fatal(err) |
| 353 | } |
| 354 | q := a.signinMail |
| 355 | t.Cleanup(q.close) |
| 356 | cancel() |
| 357 | time.Sleep(100 * time.Millisecond) |
| 358 | q.mu.RLock() |
| 359 | closed := q.closed |
| 360 | q.mu.RUnlock() |
| 361 | if closed { |
| 362 | t.Fatal("the app's context ending closed the sign-in mail queue while requests may still be finishing") |
| 363 | } |
| 364 | q.close() |
| 365 | select { |
| 366 | case <-q.done: |
| 367 | case <-time.After(2 * time.Second): |
| 368 | t.Fatal("the sign-in mail worker was still running after close") |
| 369 | } |
| 370 | } |
| 371 | |
amadan