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