| 1 | package docs |
| 2 | |
| 3 | import ( |
| 4 | "context" |
| 5 | "fmt" |
| 6 | "log/slog" |
| 7 | "sync" |
| 8 | "sync/atomic" |
| 9 | "time" |
| 10 | |
| 11 | "amadan.net/rastrillo/rastrillo/mail" |
| 12 | ) |
| 13 | |
| 14 | // mailQueue is the sign-in mailer the auth plugin is given: Send queues |
| 15 | // the link and returns at once, and one background worker decides |
| 16 | // whether the address may have it and only then talks to SMTP. |
| 17 | // |
| 18 | // Both halves are the no-oracle guarantee, measured rather than |
| 19 | // reasoned about. When the send ran inside the request, a permitted |
| 20 | // address waited for the SMTP round trip before its `303 ?sent=1` and a |
| 21 | // denied one did not: 252 ms against 0.35 ms (Astra on oficina/slides |
| 22 | // #20). A response time is an answer like any other. So POST /signin |
| 23 | // does the same synchronous work for every address — the auth plugin's |
| 24 | // budgets, its link row, this enqueue — and the one admission-dependent |
| 25 | // step, the send, happens after the response, where nobody can time it. |
| 26 | // |
| 27 | // The request path is Send, and Send does no I/O and never blocks: not |
| 28 | // a send, not an admission check, not even a log line. Every address's |
| 29 | // link is queued, permitted or not, so how full the queue is never |
| 30 | // depends on admission either; the worker decides afterwards. A full |
| 31 | // queue drops the link and counts it in an atomic; the worker logs the |
| 32 | // count when it next runs. The person is answered exactly as when the |
| 33 | // queue is empty, because a different answer for a full queue would be |
| 34 | // one more thing to read. (Astra on #20, round 2.) |
| 35 | // |
| 36 | // The worker survives a panic in the mailer: it recovers per message, |
| 37 | // logs, and keeps draining. Delivery failures are logged, never |
| 38 | // surfaced: a failure only a permitted address can reach is the oracle |
| 39 | // again. |
| 40 | // |
| 41 | // Nothing but the log pump ever writes to the logger. The worker and |
| 42 | // close hand their lines to logf, which never blocks: a buffered |
| 43 | // channel, and a counted drop when it is full. A stalled log sink can |
| 44 | // therefore hold only the pump's one write — never a request, never the |
| 45 | // worker, never close (Astra on #20, round 3). The pump ends when the |
| 46 | // worker does. |
| 47 | // |
| 48 | // close drains what is queued within drainTimeout. Past it, the send |
| 49 | // in flight is cancelled through its context, everything still queued |
| 50 | // is abandoned and counted, and close waits a short grace for the |
| 51 | // worker to stop. A mailer that ignores its context is the only way a |
| 52 | // worker outlives close; that is counted in stuck and logged, best |
| 53 | // effort, too. |
| 54 | type mailQueue struct { |
| 55 | next mail.Sender |
| 56 | admits func(to string) bool |
| 57 | // gate, when set, is read off the request's context at enqueue time |
| 58 | // and travels with the link; the worker sends only if it said yes. |
| 59 | gate func(context.Context) bool |
| 60 | logger *slog.Logger |
| 61 | |
| 62 | drainTimeout time.Duration |
| 63 | sendTimeout time.Duration |
| 64 | |
| 65 | mu sync.RWMutex // held for reading by Send, for writing by close |
| 66 | closed bool |
| 67 | jobs chan mailJob |
| 68 | dropped atomic.Int64 |
| 69 | pending sync.WaitGroup |
| 70 | |
| 71 | ctx context.Context // cancelled when close gives up waiting |
| 72 | cancel context.CancelFunc |
| 73 | done chan struct{} |
| 74 | |
| 75 | logMu sync.RWMutex // logf reads logsClosed; the worker's exit sets it |
| 76 | logsClosed bool |
| 77 | logs chan logLine // to the pump; logf never blocks on it |
| 78 | unlogged atomic.Int64 // lines handed over and not yet written |
| 79 | lostLogs atomic.Int64 // lines logf could not hand over |
| 80 | stuck atomic.Bool // close gave up on a worker that ignored cancellation |
| 81 | |
| 82 | // refusedLog, when set, is the line the worker logs (through logf, |
| 83 | // with a running count and never the address) for each link it |
| 84 | // refuses. |
| 85 | refusedLog string |
| 86 | refusals atomic.Int64 |
| 87 | } |
| 88 | |
| 89 | type logLine struct { |
| 90 | msg string |
| 91 | args []any |
| 92 | } |
| 93 | |
| 94 | type mailJob struct { |
| 95 | to, subject, body string |
| 96 | gated bool |
| 97 | } |
| 98 | |
| 99 | const ( |
| 100 | mailQueueDepth = 64 |
| 101 | mailSendTimeout = time.Minute |
| 102 | mailDrainTimeout = 30 * time.Second |
| 103 | mailAbandonGrace = 5 * time.Second |
| 104 | mailLogDepth = 32 |
| 105 | ) |
| 106 | |
| 107 | func newMailQueue(next mail.Sender, admits func(string) bool, gate func(context.Context) bool, logger *slog.Logger) *mailQueue { |
| 108 | return newMailQueueLogging(next, admits, gate, logger, "") |
| 109 | } |
| 110 | |
| 111 | // newMailQueueLogging is newMailQueue with refusedLog set (see the |
| 112 | // field). |
| 113 | func newMailQueueLogging(next mail.Sender, admits func(string) bool, gate func(context.Context) bool, logger *slog.Logger, refusedLog string) *mailQueue { |
| 114 | if logger == nil { |
| 115 | logger = slog.Default() |
| 116 | } |
| 117 | ctx, cancel := context.WithCancel(context.Background()) |
| 118 | q := &mailQueue{next: next, admits: admits, gate: gate, logger: logger, |
| 119 | drainTimeout: mailDrainTimeout, sendTimeout: mailSendTimeout, |
| 120 | jobs: make(chan mailJob, mailQueueDepth), ctx: ctx, cancel: cancel, |
| 121 | done: make(chan struct{}), logs: make(chan logLine, mailLogDepth), refusedLog: refusedLog} |
| 122 | go q.pump() |
| 123 | go q.run() |
| 124 | return q |
| 125 | } |
| 126 | |
| 127 | // Send queues one link. It never blocks, never does I/O and never |
| 128 | // fails: the request that called it answers the same way whatever |
| 129 | // happens next. |
| 130 | func (q *mailQueue) Send(ctx context.Context, to, subject, body string) error { |
| 131 | job := mailJob{to: to, subject: subject, body: body, gated: true} |
| 132 | if q.gate != nil { |
| 133 | job.gated = q.gate(ctx) |
| 134 | } |
| 135 | q.mu.RLock() |
| 136 | defer q.mu.RUnlock() |
| 137 | if q.closed { |
| 138 | q.dropped.Add(1) |
| 139 | return nil |
| 140 | } |
| 141 | q.pending.Add(1) |
| 142 | select { |
| 143 | case q.jobs <- job: |
| 144 | default: |
| 145 | q.pending.Done() |
| 146 | q.dropped.Add(1) |
| 147 | } |
| 148 | return nil |
| 149 | } |
| 150 | |
| 151 | // logf hands one error line to the pump. It never blocks: when the |
| 152 | // pump is behind, the line is counted in lostLogs instead. |
| 153 | func (q *mailQueue) logf(msg string, args ...any) { |
| 154 | q.logMu.RLock() |
| 155 | defer q.logMu.RUnlock() |
| 156 | if q.logsClosed { |
| 157 | q.lostLogs.Add(1) |
| 158 | return |
| 159 | } |
| 160 | q.unlogged.Add(1) |
| 161 | select { |
| 162 | case q.logs <- logLine{msg: msg, args: args}: |
| 163 | default: |
| 164 | q.unlogged.Add(-1) |
| 165 | q.lostLogs.Add(1) |
| 166 | } |
| 167 | } |
| 168 | |
| 169 | // pump is the only goroutine that writes to the logger. It ends when |
| 170 | // the worker closes logs on its way out. |
| 171 | // |
| 172 | // Its limit, stated rather than engineered around: a write blocked |
| 173 | // inside the logger (a stalled sink) cannot be interrupted from Go. It |
| 174 | // can only finish, or die with the process. Closing logs does not reach |
| 175 | // it mid-write, so a stalled sink leaves this one goroutine behind |
| 176 | // until the sink moves. Nothing else waits on it: not Send, not the |
| 177 | // worker, not close. |
| 178 | func (q *mailQueue) pump() { |
| 179 | for l := range q.logs { |
| 180 | if n := q.lostLogs.Swap(0); n > 0 { |
| 181 | q.logger.Error("docs: sign-in mail log lines lost to a slow log sink", "count", n) |
| 182 | } |
| 183 | q.logger.Error(l.msg, l.args...) |
| 184 | q.unlogged.Add(-1) |
| 185 | } |
| 186 | } |
| 187 | |
| 188 | func (q *mailQueue) run() { |
| 189 | defer close(q.done) |
| 190 | defer func() { // after the last logf below; ends the pump |
| 191 | q.logMu.Lock() |
| 192 | q.logsClosed = true |
| 193 | close(q.logs) |
| 194 | q.logMu.Unlock() |
| 195 | }() |
| 196 | abandoned := 0 |
| 197 | for job := range q.jobs { |
| 198 | q.reportDrops() |
| 199 | if q.ctx.Err() != nil { |
| 200 | abandoned++ |
| 201 | } else { |
| 202 | q.deliver(job) |
| 203 | } |
| 204 | q.pending.Done() |
| 205 | } |
| 206 | q.reportDrops() |
| 207 | if abandoned > 0 { |
| 208 | q.logf("docs: sign-in links abandoned at shutdown", "count", abandoned) |
| 209 | } |
| 210 | } |
| 211 | |
| 212 | // reportDrops logs the links Send had to drop since the last report. |
| 213 | // Here, on the worker, so the request path never writes a log line. |
| 214 | func (q *mailQueue) reportDrops() { |
| 215 | if n := q.dropped.Swap(0); n > 0 { |
| 216 | q.logf("docs: sign-in mail queue full; links dropped", "count", n) |
| 217 | } |
| 218 | } |
| 219 | |
| 220 | // deliver sends one link if it may go. A panic in the admission check |
| 221 | // or the mailer is this message's failure, not the process's. |
| 222 | func (q *mailQueue) deliver(job mailJob) { |
| 223 | defer func() { |
| 224 | if p := recover(); p != nil { |
| 225 | q.logf("docs: sign-in mail worker recovered from a panic", "panic", fmt.Sprint(p)) |
| 226 | } |
| 227 | }() |
| 228 | if !job.gated || !q.admits(job.to) { |
| 229 | // Not admitted: the link the auth plugin stored is never |
| 230 | // delivered, so it is never redeemed. No address in the log. |
| 231 | if q.refusedLog != "" { |
| 232 | q.logf(q.refusedLog, "stage", "signin.gate", "refusals_since_boot", q.refusals.Add(1)) |
| 233 | } |
| 234 | return |
| 235 | } |
| 236 | ctx, cancel := context.WithTimeout(q.ctx, q.sendTimeout) |
| 237 | defer cancel() |
| 238 | if err := q.next.Send(ctx, job.to, job.subject, job.body); err != nil { |
| 239 | q.logf("docs: send sign-in link", "err", err) |
| 240 | } |
| 241 | } |
| 242 | |
| 243 | // wait blocks until every link queued so far has been sent or refused, |
| 244 | // and every line logged about them has been written. Tests use it to |
| 245 | // read the mailer, and the log, afterwards. |
| 246 | func (q *mailQueue) wait() { |
| 247 | q.pending.Wait() |
| 248 | for q.unlogged.Load() > 0 { |
| 249 | time.Sleep(time.Millisecond) |
| 250 | } |
| 251 | } |
| 252 | |
| 253 | // close stops taking links and drains what is queued, within |
| 254 | // drainTimeout; then it cancels, abandons the rest, and stops the |
| 255 | // worker (see the type's comment). It never waits on the log pump: |
| 256 | // shutdown deliberately does not wait for a write blocked inside the |
| 257 | // logger, which can only finish or die with the process (see pump). |
| 258 | func (q *mailQueue) close() { |
| 259 | q.mu.Lock() |
| 260 | if q.closed { |
| 261 | q.mu.Unlock() |
| 262 | return |
| 263 | } |
| 264 | q.closed = true |
| 265 | close(q.jobs) |
| 266 | q.mu.Unlock() |
| 267 | defer q.cancel() |
| 268 | select { |
| 269 | case <-q.done: |
| 270 | return |
| 271 | case <-time.After(q.drainTimeout): |
| 272 | } |
| 273 | q.cancel() |
| 274 | select { |
| 275 | case <-q.done: |
| 276 | case <-time.After(mailAbandonGrace): |
| 277 | // Counted, not written: logging here could hang close on the |
| 278 | // very sink that may be the trouble. The worker is still running, |
| 279 | // so logf is still safe to call, and never blocks. |
| 280 | q.stuck.Store(true) |
| 281 | q.logf("docs: sign-in mail worker ignored cancellation; left running") |
| 282 | } |
| 283 | } |
| 284 | |
amadan