| 1 | package slides |
| 2 | |
| 3 | import ( |
| 4 | "context" |
| 5 | "fmt" |
| 6 | "log/slog" |
| 7 | "runtime" |
| 8 | "strings" |
| 9 | "sync" |
| 10 | "testing" |
| 11 | "time" |
| 12 | ) |
| 13 | |
| 14 | // stuckHandler is a slog handler whose every write blocks until release |
| 15 | // is closed: a log sink that has stalled, as a full pipe does. It |
| 16 | // remembers what it was finally allowed to write. |
| 17 | type stuckHandler struct { |
| 18 | release chan struct{} |
| 19 | mu *sync.Mutex |
| 20 | msgs *[]string |
| 21 | } |
| 22 | |
| 23 | func (h stuckHandler) Enabled(context.Context, slog.Level) bool { return true } |
| 24 | func (h stuckHandler) Handle(_ context.Context, r slog.Record) error { |
| 25 | <-h.release |
| 26 | h.mu.Lock() |
| 27 | *h.msgs = append(*h.msgs, r.Message) |
| 28 | h.mu.Unlock() |
| 29 | return nil |
| 30 | } |
| 31 | func (h stuckHandler) WithAttrs([]slog.Attr) slog.Handler { return h } |
| 32 | func (h stuckHandler) WithGroup(string) slog.Handler { return h } |
| 33 | |
| 34 | // funcSender adapts a function to mail.Sender. |
| 35 | type funcSender func(ctx context.Context, to string) error |
| 36 | |
| 37 | func (f funcSender) Send(ctx context.Context, to, _, _ string) error { return f(ctx, to) } |
| 38 | |
| 39 | func everyone(string) bool { return true } |
| 40 | |
| 41 | // TestMailQueueSendNeverBlocksWhenFull: Send is the request path, so it |
| 42 | // may not block or do I/O even when the queue is full — not even to log |
| 43 | // the drop (Astra on oficina/slides #20, round 2, P1: a "queue full" log |
| 44 | // line on a stalled sink held the request, and saturation is |
| 45 | // admission-dependent). The worker is stuck on its first link and the |
| 46 | // log sink is stuck too; twice the queue's depth of Sends must still |
| 47 | // return at once, and the drops are logged by the worker afterwards. |
| 48 | func TestMailQueueSendNeverBlocksWhenFull(t *testing.T) { |
| 49 | release := make(chan struct{}) |
| 50 | var once sync.Once |
| 51 | free := func() { once.Do(func() { close(release) }) } |
| 52 | stuck := funcSender(func(ctx context.Context, _ string) error { |
| 53 | select { |
| 54 | case <-release: |
| 55 | case <-ctx.Done(): |
| 56 | } |
| 57 | return nil |
| 58 | }) |
| 59 | var mu sync.Mutex |
| 60 | var msgs []string |
| 61 | q := newMailQueue(stuck, everyone, nil, slog.New(stuckHandler{release, &mu, &msgs})) |
| 62 | t.Cleanup(func() { free(); q.close() }) |
| 63 | |
| 64 | done := make(chan struct{}) |
| 65 | go func() { |
| 66 | for i := 0; i < 2*mailQueueDepth; i++ { |
| 67 | _ = q.Send(context.Background(), fmt.Sprintf("p%d@example.test", i), "s", "b") |
| 68 | } |
| 69 | close(done) |
| 70 | }() |
| 71 | select { |
| 72 | case <-done: |
| 73 | case <-time.After(2 * time.Second): |
| 74 | free() |
| 75 | <-done |
| 76 | t.Fatal("Send blocked with the queue full: the request path waited on the queue or the log") |
| 77 | } |
| 78 | // The drops are the worker's to log, through the pump, once the |
| 79 | // sink is free. |
| 80 | free() |
| 81 | q.close() |
| 82 | deadline := time.Now().Add(2 * time.Second) |
| 83 | for time.Now().Before(deadline) { |
| 84 | mu.Lock() |
| 85 | for _, m := range msgs { |
| 86 | if strings.Contains(m, "links dropped") { |
| 87 | mu.Unlock() |
| 88 | return |
| 89 | } |
| 90 | } |
| 91 | mu.Unlock() |
| 92 | time.Sleep(5 * time.Millisecond) |
| 93 | } |
| 94 | t.Fatalf("no drop was logged with twice the queue's depth sent; the log has %q", msgs) |
| 95 | } |
| 96 | |
| 97 | // TestMailQueueQueuesEveryAddress: the queue's fill level must not |
| 98 | // depend on admission, so Send queues a refused address's link exactly |
| 99 | // as it queues a permitted one; only the worker asks. |
| 100 | func TestMailQueueQueuesEveryAddress(t *testing.T) { |
| 101 | release := make(chan struct{}) |
| 102 | stuck := funcSender(func(ctx context.Context, _ string) error { |
| 103 | select { |
| 104 | case <-release: |
| 105 | case <-ctx.Done(): |
| 106 | } |
| 107 | return nil |
| 108 | }) |
| 109 | var asked sync.Map |
| 110 | admits := func(to string) bool { asked.Store(to, true); return to == "first@example.test" } |
| 111 | q := newMailQueue(stuck, admits, nil, slog.New(slog.DiscardHandler)) |
| 112 | t.Cleanup(func() { close(release); q.close() }) |
| 113 | _ = q.Send(context.Background(), "first@example.test", "s", "b") |
| 114 | deadline := time.Now().Add(2 * time.Second) |
| 115 | for _, ok := asked.Load("first@example.test"); !ok && time.Now().Before(deadline); _, ok = asked.Load("first@example.test") { |
| 116 | time.Sleep(5 * time.Millisecond) |
| 117 | } |
| 118 | for i := 0; i < 5; i++ { |
| 119 | _ = q.Send(context.Background(), fmt.Sprintf("refused%d@example.test", i), "s", "b") |
| 120 | } |
| 121 | if got := len(q.jobs); got != 5 { |
| 122 | t.Fatalf("queued %d refused links, want all 5: fill level must not depend on admission", got) |
| 123 | } |
| 124 | } |
| 125 | |
| 126 | // TestMailQueueSurvivesAPanic: a panic in the mailer is that message's |
| 127 | // failure; the worker recovers, logs, and sends the next one (Astra, |
| 128 | // round 2, P2). |
| 129 | func TestMailQueueSurvivesAPanic(t *testing.T) { |
| 130 | var mu sync.Mutex |
| 131 | var sent []string |
| 132 | calls := 0 |
| 133 | s := funcSender(func(_ context.Context, to string) error { |
| 134 | mu.Lock() |
| 135 | defer mu.Unlock() |
| 136 | calls++ |
| 137 | if calls == 1 { |
| 138 | panic("mailer exploded") |
| 139 | } |
| 140 | sent = append(sent, to) |
| 141 | return nil |
| 142 | }) |
| 143 | q := newMailQueue(s, everyone, nil, slog.New(slog.DiscardHandler)) |
| 144 | t.Cleanup(q.close) |
| 145 | _ = q.Send(context.Background(), "first@example.test", "s", "b") |
| 146 | _ = q.Send(context.Background(), "second@example.test", "s", "b") |
| 147 | q.wait() |
| 148 | mu.Lock() |
| 149 | defer mu.Unlock() |
| 150 | if len(sent) != 1 || sent[0] != "second@example.test" { |
| 151 | t.Fatalf("sent = %v, want the second link after the first panicked", sent) |
| 152 | } |
| 153 | } |
| 154 | |
| 155 | // TestMailQueueCloseIsBoundedAndStopsTheWorker: close drains within its |
| 156 | // deadline, then cancels the send in flight, abandons the rest, and the |
| 157 | // worker is gone — no goroutine outlives close (Astra, round 2, P2). |
| 158 | func TestMailQueueCloseIsBoundedAndStopsTheWorker(t *testing.T) { |
| 159 | baseline := runtime.NumGoroutine() |
| 160 | honours := funcSender(func(ctx context.Context, _ string) error { |
| 161 | <-ctx.Done() // a relay that never answers, but obeys cancellation |
| 162 | return ctx.Err() |
| 163 | }) |
| 164 | q := newMailQueue(honours, everyone, nil, slog.New(slog.DiscardHandler)) |
| 165 | q.drainTimeout = 50 * time.Millisecond |
| 166 | for i := 0; i < 3; i++ { |
| 167 | _ = q.Send(context.Background(), fmt.Sprintf("p%d@example.test", i), "s", "b") |
| 168 | } |
| 169 | start := time.Now() |
| 170 | q.close() |
| 171 | if took := time.Since(start); took > 2*time.Second { |
| 172 | t.Fatalf("close took %v, want about its 50ms deadline", took) |
| 173 | } |
| 174 | select { |
| 175 | case <-q.done: |
| 176 | default: |
| 177 | t.Fatal("the worker was still running after close") |
| 178 | } |
| 179 | deadline := time.Now().Add(time.Second) |
| 180 | for runtime.NumGoroutine() > baseline && time.Now().Before(deadline) { |
| 181 | time.Sleep(5 * time.Millisecond) |
| 182 | } |
| 183 | if n := runtime.NumGoroutine(); n > baseline { |
| 184 | t.Fatalf("%d goroutines after close, %d before: the queue leaked", n, baseline) |
| 185 | } |
| 186 | } |
| 187 | |
| 188 | // TestAppCloseStopsTheMailWorker: the app owns its queue, and Close |
| 189 | // stops its worker — no test that builds an app and closes it leaves |
| 190 | // one running behind it. |
| 191 | func TestAppCloseStopsTheMailWorker(t *testing.T) { |
| 192 | _, a, err := New(testDB(t), Config{Env: EnvDevelopment, Origin: "http://localhost:8091", Logger: quietLogger()}) |
| 193 | if err != nil { |
| 194 | t.Fatal(err) |
| 195 | } |
| 196 | q := a.mail |
| 197 | if err := a.Close(); err != nil { |
| 198 | t.Fatal(err) |
| 199 | } |
| 200 | select { |
| 201 | case <-q.done: |
| 202 | case <-time.After(2 * time.Second): |
| 203 | t.Fatal("the sign-in mail worker was still running after app.Close") |
| 204 | } |
| 205 | } |
| 206 | |
| 207 | // mailWorkers counts goroutines running a sign-in mail queue's worker |
| 208 | // or log pump — the targeted leak check (goleak's idea, without the |
| 209 | // dependency) TestMain runs after the package's tests. |
| 210 | func mailWorkers() int { |
| 211 | buf := make([]byte, 1<<22) |
| 212 | stacks := string(buf[:runtime.Stack(buf, true)]) |
| 213 | return strings.Count(stacks, "(*mailQueue).run(") + strings.Count(stacks, "(*mailQueue).pump(") |
| 214 | } |
| 215 | |
| 216 | // TestMailQueueCloseIsBoundedWithAStalledLogger: close reports through |
| 217 | // nothing that can block, and never waits on the log pump. With the log |
| 218 | // sink stalled — every write hangs — and a relay that never answers but |
| 219 | // honours cancellation, and WHILE THE SINK IS STILL STALLED: |
| 220 | // |
| 221 | // - close returns within its bound; |
| 222 | // - the mail worker has exited; |
| 223 | // - at most the one log pump remains, blocked in its write. |
| 224 | // |
| 225 | // A write blocked inside the logger cannot be interrupted from Go; it |
| 226 | // can only finish or die with the process, and shutdown deliberately |
| 227 | // does not wait for it. So only once the sink is released must the pump |
| 228 | // exit and the goroutine count return to its baseline (Astra on #20, |
| 229 | // rounds 3 and 4). The test fails if close waited on the pump, or if |
| 230 | // the pump could hold the worker. |
| 231 | func TestMailQueueCloseIsBoundedWithAStalledLogger(t *testing.T) { |
| 232 | waitFor := func(cond func() bool) bool { |
| 233 | deadline := time.Now().Add(2 * time.Second) |
| 234 | for !cond() && time.Now().Before(deadline) { |
| 235 | time.Sleep(5 * time.Millisecond) |
| 236 | } |
| 237 | return cond() |
| 238 | } |
| 239 | baseline := runtime.NumGoroutine() |
| 240 | release := make(chan struct{}) |
| 241 | var once sync.Once |
| 242 | free := func() { once.Do(func() { close(release) }) } |
| 243 | t.Cleanup(free) |
| 244 | var mu sync.Mutex |
| 245 | var msgs []string |
| 246 | honours := funcSender(func(ctx context.Context, _ string) error { |
| 247 | <-ctx.Done() |
| 248 | return ctx.Err() |
| 249 | }) |
| 250 | q := newMailQueue(honours, everyone, nil, slog.New(stuckHandler{release, &mu, &msgs})) |
| 251 | q.drainTimeout = 50 * time.Millisecond |
| 252 | for i := 0; i < 2*mailQueueDepth; i++ { // drops too, so there is plenty to log |
| 253 | _ = q.Send(context.Background(), fmt.Sprintf("p%d@example.test", i), "s", "b") |
| 254 | } |
| 255 | closed := make(chan struct{}) |
| 256 | go func() { q.close(); close(closed) }() |
| 257 | select { |
| 258 | case <-closed: |
| 259 | case <-time.After(2 * time.Second): |
| 260 | free() |
| 261 | <-closed |
| 262 | t.Fatal("close hung on a stalled log sink") |
| 263 | } |
| 264 | |
| 265 | // The sink is still stalled. |
| 266 | select { |
| 267 | case <-q.done: |
| 268 | default: |
| 269 | t.Fatal("the worker was still running after close, held by the stalled log sink") |
| 270 | } |
| 271 | if !waitFor(func() bool { return runtime.NumGoroutine() <= baseline+1 }) { |
| 272 | t.Fatalf("%d goroutines with the sink stalled, %d before: more than the one blocked log pump remains", runtime.NumGoroutine(), baseline) |
| 273 | } |
| 274 | if n := mailWorkers(); n > 1 { |
| 275 | t.Fatalf("%d mail queue goroutines with the sink stalled, want at most the log pump", n) |
| 276 | } |
| 277 | |
| 278 | // Released, the pump finishes its write and exits. |
| 279 | free() |
| 280 | if !waitFor(func() bool { return mailWorkers() == 0 && runtime.NumGoroutine() <= baseline }) { |
| 281 | t.Fatalf("after release: %d mail queue goroutines, %d goroutines against %d before", mailWorkers(), runtime.NumGoroutine(), baseline) |
| 282 | } |
| 283 | } |
| 284 | |
amadan