amadan
Send sign-in mail after the response, so its timing says nothing
The same timing split Astra found in Slides (#20, P1): an admitted address waited for SMTP before its ?sent=1 and a stranger did not (252 ms against 0.35 ms there), so the team was readable off a stopwatch, forced posts included. auth's Mailer is now mailQueue: Send queues and returns at once, and one worker asks App.Admits and only then talks to SMTP; failures are logged, never answered. Bounded (64; a full queue drops with a log line), and main drains it once Serve returns (DrainSigninMail). The test recorder waits for the queue before it is read. TestSigninNeverWaitsForTheMailer blocks the mailer and requires every POST — admitted, stranger, both with force=1 — to answer, then the admitted links to go out. It fails on 2dfacac.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
6 files changed,
+287
−29
cmd/sheets/main.go+5 −1internal/sheets/auth.go+9 −2internal/sheets/begin.go+5 −26internal/sheets/begin_test.go+21 −0internal/sheets/mailqueue.go+147 −0internal/sheets/signin_timing_test.go+100 −0
CI passed — run details
CI log
amadan: .amadan/timeout: this job's budget is 15m0s (this runner allows up to 30m0s) === vet === CGO_ENABLED=0 go vet ./... CGO_ENABLED=0 go vet -tags browser ./internal/sheets/ === fmt === === build === CGO_ENABLED=0 go build ./... === migrations === go tool rastrillo migration check rastrillo migration check: models and migrations agree === go-test === CGO_ENABLED=0 go test -count=1 ./... ? amadan.net/oficina/sheets/cmd/sheets [no test files] ok amadan.net/oficina/sheets/internal/guardstest 0.087s ok amadan.net/oficina/sheets/internal/sheets 3.852s ok amadan.net/oficina/sheets/internal/sheets/calc 0.008s ok amadan.net/oficina/sheets/internal/sheets/format 0.003s ? amadan.net/oficina/sheets/internal/sheets/keymailtest [no test files] ok amadan.net/oficina/sheets/internal/sheets/live 0.053s ok amadan.net/oficina/sheets/internal/sheets/seal 0.003s ok amadan.net/oficina/sheets/internal/sheets/sealtest 0.003s ok amadan.net/oficina/sheets/internal/sheets/store 2.920s ok amadan.net/oficina/sheets/internal/sheets/xlsx 0.301s ? amadan.net/oficina/sheets/tools/gencorpus [no test files] === race === go test -race -count=1 ./internal/sheets/store/... ./internal/sheets/live/... ok amadan.net/oficina/sheets/internal/sheets/store 47.735s ok amadan.net/oficina/sheets/internal/sheets/live 1.066s
diff --git a/cmd/sheets/main.go b/cmd/sheets/main.go| index 68e781d..7fa5f19 100644 |
| --- a/cmd/sheets/main.go |
| +++ b/cmd/sheets/main.go |
| @@ -128,7 +128,11 @@ func main() { |
| // otherwise Serve would open a second connection to the same file. |
| opts.DBPath = "" |
| - if err := rastrillo.Serve(opts); err != nil { |
| + err = rastrillo.Serve(opts) |
| + // Sign-in links are sent after the response (mailqueue.go); send |
| + // what is still queued before the process goes. |
| + sheets.DrainSigninMail() |
| + if err != nil { |
| logger.Error("serve", "err", err) |
| os.Exit(1) |
| } |
diff --git a/internal/sheets/auth.go b/internal/sheets/auth.go| index 752eeae..6e52b09 100644 |
| --- a/internal/sheets/auth.go |
| +++ b/internal/sheets/auth.go |
| @@ -151,6 +151,13 @@ func NewAuth(db *sql.DB, env AuthEnv, logger *slog.Logger, authorize func(string |
| // is the version that says so. |
| return nil, errors.New("sign-in: refusing to wire auth with no admission gate") |
| } |
| + queue := newMailQueue(env.Mailer, authorize, logger) |
| + if a, ok := env.Mailer.(queueAttacher); ok { |
| + a.attachQueue(queue.wait) |
| + } |
| + signinQueuesMu.Lock() |
| + signinQueues = append(signinQueues, queue) |
| + signinQueuesMu.Unlock() |
| signedInPath := "/sheets" |
| if env.Home != nil { |
| signedInPath = connect.LocalCompletePath |
| @@ -160,8 +167,8 @@ func NewAuth(db *sql.DB, env AuthEnv, logger *slog.Logger, authorize func(string |
| Origin: env.Origin, |
| InstanceKey: env.InstanceKey, |
| // Begin runs for every address (handleBegin); the mail goes |
| - // only to one authorize admits. |
| - Mailer: admissionMailer{next: env.Mailer, admits: authorize}, |
| + // out after the response, and only to one authorize admits. |
| + Mailer: queue, |
| Authorize: authorize, |
| SigninPath: "/signin", |
| // Where a fresh session lands. auth defaults this to "/", |
diff --git a/internal/sheets/begin.go b/internal/sheets/begin.go| index b551dcc..1befcf4 100644 |
| --- a/internal/sheets/begin.go |
| +++ b/internal/sheets/begin.go |
| @@ -2,12 +2,10 @@ package sheets |
| import ( |
| "bytes" |
| - "context" |
| "net/http" |
| "strings" |
| "amadan.net/oficina/home/connect" |
| - "amadan.net/rastrillo/rastrillo/mail" |
| ) |
| // handleBegin is POST /signin, in both modes: auth's Begin for EVERY |
| @@ -31,8 +29,9 @@ import ( |
| // the address, by auth's Authorize (App.Admits), and a refusal is |
| // the door saying so (doorOnRefusal), told only to someone who has |
| // just proved they hold the address. |
| -// - Any other address is answered ?sent=1, and admissionMailer mails |
| -// the link only if App.Admits says yes. Without that, anyone who |
| +// - Any other address is answered ?sent=1, and mailQueue mails the |
| +// link only if App.Admits says yes — after the response, in a |
| +// worker, so not even the response time differs (mailqueue.go). Without that, anyone who |
| // can reach the instance could make it email a live sign-in link to |
| // any address they name — abuse of our sending identity, found by |
| // POSTing a stranger's address at the deployed instance. The cost |
| @@ -41,8 +40,8 @@ import ( |
| // |
| // Both kinds of address spend the same rate budgets and are parsed the |
| // same way, so ?err=rate and ?err=address say nothing about admission |
| -// either. The one outcome only an admitted address can reach is ?err=1 |
| -// from a send that failed, an operational fault rather than an answer. |
| +// either; and since the send happens after the response, a failed one |
| +// is logged rather than answered. |
| // |
| // It used to gate admission in front of Begin instead, which answered a |
| // non-admitted Keymail address ?sent=1 and sent an admitted one to |
| @@ -51,26 +50,6 @@ func (a *App) handleBegin(w http.ResponseWriter, r *http.Request) { |
| connect.OAuthContinuation(a.origin, a.auth.Begin, a.renderHomeOAuth)(w, r) |
| } |
| -// admissionMailer is the mail half of admission: Begin runs for every |
| -// address (handleBegin), and this is where one App.Admits refuses is |
| -// quietly not mailed. App.Admits, NOT the static owners list: the two |
| -// must ask the same question as auth's own Authorize, or a guest |
| -// somebody shared a sheet with would be admitted at redemption and |
| -// never sent a link to redeem. auth has already stored an expiring |
| -// token by the time it calls Send; one never delivered is never |
| -// redeemed, and Authorize would refuse it if it were. |
| -type admissionMailer struct { |
| - next mail.Sender |
| - admits func(string) bool |
| -} |
| - |
| -func (m admissionMailer) Send(ctx context.Context, to, subject, body string) error { |
| - if !m.admits(to) { |
| - return nil |
| - } |
| - return m.next.Send(ctx, to, subject, body) |
| -} |
| - |
| // authRefusal is the bare-text body rastrillo/auth's admit() writes, with |
| // a 403, when a verified address is not admitted. rastrillo at the |
| // version pinned here has no hook to render anything else, so |
diff --git a/internal/sheets/begin_test.go b/internal/sheets/begin_test.go| index 53a4d65..f767cf2 100644 |
| --- a/internal/sheets/begin_test.go |
| +++ b/internal/sheets/begin_test.go |
| @@ -22,6 +22,25 @@ type recorder struct { |
| mu sync.Mutex |
| sent []string |
| bodies []string |
| + // waits are the sign-in mail queues in front of this recorder: |
| + // links go out after the response (mailqueue.go), so every read |
| + // waits for them first. |
| + waits []func() |
| +} |
| + |
| +func (m *recorder) attachQueue(wait func()) { |
| + m.mu.Lock() |
| + m.waits = append(m.waits, wait) |
| + m.mu.Unlock() |
| +} |
| + |
| +func (m *recorder) flush() { |
| + m.mu.Lock() |
| + waits := append([]func(){}, m.waits...) |
| + m.mu.Unlock() |
| + for _, w := range waits { |
| + w() |
| + } |
| } |
| func (m *recorder) Send(_ context.Context, to, _, body string) error { |
| @@ -35,6 +54,7 @@ func (m *recorder) Send(_ context.Context, to, _, body string) error { |
| // lastLink pulls the verify URL out of the most recent email. |
| func (m *recorder) lastLink(t *testing.T) string { |
| t.Helper() |
| + m.flush() |
| m.mu.Lock() |
| defer m.mu.Unlock() |
| if len(m.bodies) == 0 { |
| @@ -49,6 +69,7 @@ func (m *recorder) lastLink(t *testing.T) string { |
| } |
| func (m *recorder) addresses() []string { |
| + m.flush() |
| m.mu.Lock() |
| defer m.mu.Unlock() |
| return append([]string(nil), m.sent...) |
diff --git a/internal/sheets/mailqueue.go b/internal/sheets/mailqueue.go| new file mode 100644 |
| index 0000000..86ae141 |
| --- /dev/null |
| +++ b/internal/sheets/mailqueue.go |
| @@ -0,0 +1,147 @@ |
| +package sheets |
| + |
| +import ( |
| + "context" |
| + "log/slog" |
| + "sync" |
| + "time" |
| + |
| + "amadan.net/rastrillo/rastrillo/mail" |
| +) |
| + |
| +// mailQueue is the sign-in mailer rauth is given: Send queues the link |
| +// and returns at once, and one background worker asks App.Admits and |
| +// only then talks to SMTP. |
| +// |
| +// Both halves are the no-oracle guarantee (handleBegin), measured rather |
| +// than reasoned about. When the send ran inside the request, a permitted |
| +// address waited for the SMTP round trip before its `303 ?sent=1` and a |
| +// denied one did not: 252 ms against 0.35 ms (Astra on oficina/slides #20; Sheets had the same split). A response |
| +// time is an answer like any other. So POST /signin does the same |
| +// synchronous work for every address — rauth's budgets, its link row, |
| +// this enqueue — and the one admission-dependent step, the send, happens |
| +// after the response, where nobody can time it. The admission check |
| +// moved into the worker for the same reason: a check before responding |
| +// would be a branch an attacker could time, however cheap it is today. |
| +// |
| +// Delivery failures are logged, never surfaced. A failure only a |
| +// permitted address can reach is the oracle again, and the person is |
| +// told what every address is told: check your email, or ask again. |
| +// |
| +// Bounded: a queue of mailQueueDepth links. A full queue drops the link |
| +// with a log line instead of blocking a request — the per-IP and |
| +// per-address budgets inside Begin keep that from being an ordinary |
| +// event. Close drains what is queued, within mailDrainTimeout. |
| +type mailQueue struct { |
| + next mail.Sender |
| + admits func(string) bool |
| + logger *slog.Logger |
| + |
| + mu sync.Mutex |
| + closed bool |
| + jobs chan mailJob |
| + pending sync.WaitGroup |
| + done chan struct{} |
| +} |
| + |
| +type mailJob struct{ to, subject, body string } |
| + |
| +const ( |
| + mailQueueDepth = 64 |
| + mailSendTimeout = time.Minute |
| + mailDrainTimeout = 30 * time.Second |
| +) |
| + |
| +func newMailQueue(next mail.Sender, admits func(string) bool, logger *slog.Logger) *mailQueue { |
| + if logger == nil { |
| + logger = slog.Default() |
| + } |
| + q := &mailQueue{next: next, admits: admits, logger: logger, |
| + jobs: make(chan mailJob, mailQueueDepth), done: make(chan struct{})} |
| + go q.run() |
| + return q |
| +} |
| + |
| +// Send queues one link. It never blocks and never fails: the request |
| +// that called it answers the same way whatever happens next. |
| +func (q *mailQueue) Send(_ context.Context, to, subject, body string) error { |
| + q.mu.Lock() |
| + defer q.mu.Unlock() |
| + if q.closed { |
| + q.logger.Error("sheets: sign-in mail after shutdown; dropped") |
| + return nil |
| + } |
| + q.pending.Add(1) |
| + select { |
| + case q.jobs <- mailJob{to: to, subject: subject, body: body}: |
| + default: |
| + q.pending.Done() |
| + q.logger.Error("sheets: sign-in mail queue full; link dropped") |
| + } |
| + return nil |
| +} |
| + |
| +func (q *mailQueue) run() { |
| + defer close(q.done) |
| + for job := range q.jobs { |
| + q.deliver(job) |
| + q.pending.Done() |
| + } |
| +} |
| + |
| +func (q *mailQueue) deliver(job mailJob) { |
| + if !q.admits(job.to) { |
| + // Not admitted: the link auth stored is never |
| + // delivered, so it is never redeemed. No address in the log. |
| + return |
| + } |
| + ctx, cancel := context.WithTimeout(context.Background(), mailSendTimeout) |
| + defer cancel() |
| + if err := q.next.Send(ctx, job.to, job.subject, job.body); err != nil { |
| + q.logger.Error("sheets: send sign-in link", "err", err) |
| + } |
| +} |
| + |
| +// wait blocks until every link queued so far has been delivered or |
| +// dropped. Tests use it (attachQueue) to read the mailer afterwards. |
| +func (q *mailQueue) wait() { q.pending.Wait() } |
| + |
| +// close stops taking links and drains what is queued. |
| +func (q *mailQueue) close() { |
| + q.mu.Lock() |
| + if q.closed { |
| + q.mu.Unlock() |
| + return |
| + } |
| + q.closed = true |
| + close(q.jobs) |
| + q.mu.Unlock() |
| + select { |
| + case <-q.done: |
| + case <-time.After(mailDrainTimeout): |
| + q.logger.Error("sheets: sign-in mail still sending at shutdown; abandoned") |
| + } |
| +} |
| + |
| +// signinQueues is every queue NewAuth built, so DrainSigninMail can |
| +// send what is still queued when the process stops. |
| +var ( |
| + signinQueuesMu sync.Mutex |
| + signinQueues []*mailQueue |
| +) |
| + |
| +// DrainSigninMail stops every sign-in mail queue and sends what is |
| +// still in it. main calls it once Serve returns. |
| +func DrainSigninMail() { |
| + signinQueuesMu.Lock() |
| + qs := signinQueues |
| + signinQueues = nil |
| + signinQueuesMu.Unlock() |
| + for _, q := range qs { |
| + q.close() |
| + } |
| +} |
| + |
| +// queueAttacher is a test mailer that wants to wait for the queue in |
| +// front of it before it is read (helpers_test.go's recorder). |
| +type queueAttacher interface{ attachQueue(wait func()) } |
diff --git a/internal/sheets/signin_timing_test.go b/internal/sheets/signin_timing_test.go| new file mode 100644 |
| index 0000000..abb85af |
| --- /dev/null |
| +++ b/internal/sheets/signin_timing_test.go |
| @@ -0,0 +1,100 @@ |
| +package sheets |
| + |
| +import ( |
| + "context" |
| + "net/http/httptest" |
| + "net/url" |
| + "path/filepath" |
| + "sync" |
| + "testing" |
| + "time" |
| + |
| + rdb "amadan.net/rastrillo/rastrillo/db" |
| + "amadan.net/rastrillo/rastrillo/migrate" |
| + |
| + "amadan.net/oficina/sheets/internal/sheets/seal" |
| +) |
| + |
| +// blockingMailer holds every Send until release is closed — an SMTP |
| +// relay that takes as long as the test likes. |
| +type blockingMailer struct { |
| + release chan struct{} |
| + mu sync.Mutex |
| + to []string |
| +} |
| + |
| +func (m *blockingMailer) Send(_ context.Context, to, _, _ string) error { |
| + <-m.release |
| + m.mu.Lock() |
| + m.to = append(m.to, to) |
| + m.mu.Unlock() |
| + return nil |
| +} |
| + |
| +func (m *blockingMailer) sent() []string { |
| + m.mu.Lock() |
| + defer m.mu.Unlock() |
| + return append([]string(nil), m.to...) |
| +} |
| + |
| +// TestSigninNeverWaitsForTheMailer: when the send ran inside the |
| +// request, an admitted address waited for SMTP before its ?sent=1 and a |
| +// stranger did not (Astra measured 252 ms against 0.35 ms on Slides, |
| +// which had the same shape), so the team was readable off a stopwatch. |
| +// With the mailer blocked, every POST — admitted, stranger, and both |
| +// with force=1 — must answer, and the admitted links must then go out. |
| +func TestSigninNeverWaitsForTheMailer(t *testing.T) { |
| + d, err := rdb.Open(filepath.Join(t.TempDir(), "test.db"), quietLogger()) |
| + if err != nil { |
| + t.Fatal(err) |
| + } |
| + t.Cleanup(func() { d.Close() }) |
| + if _, err := migrate.Apply(context.Background(), d, BootSchema); err != nil { |
| + t.Fatal(err) |
| + } |
| + sealer, err := seal.New(make([]byte, dekBytes)) |
| + if err != nil { |
| + t.Fatal(err) |
| + } |
| + app := New(Config{DB: d.G, Sealer: sealer, Origin: testOrigin, Admit: Admits([]string{signedInAddress})}) |
| + bm := &blockingMailer{release: make(chan struct{})} |
| + a, err := NewAuth(d.Writer(), AuthEnv{Origin: testOrigin, InstanceKey: "test-instance-key", Owners: []string{signedInAddress}, Mailer: bm}, quietLogger(), app.Admits) |
| + if err != nil { |
| + t.Fatal(err) |
| + } |
| + app.UseAuth(a) |
| + var once sync.Once |
| + free := func() { once.Do(func() { close(bm.release) }) } |
| + t.Cleanup(free) |
| + h := app.Router() |
| + |
| + for _, form := range []url.Values{ |
| + {"address": {signedInAddress}}, |
| + {"address": {"stranger@example.com"}}, |
| + {"address": {signedInAddress}, "force": {"1"}}, |
| + {"address": {"stranger@example.com"}, "force": {"1"}}, |
| + } { |
| + done := make(chan *httptest.ResponseRecorder, 1) |
| + go func() { done <- keymailPost(t, h, form) }() |
| + select { |
| + case rec := <-done: |
| + if rec.Code != 303 || rec.Header().Get("Location") != "/signin?sent=1" { |
| + t.Errorf("POST %v: %d %q, want 303 /signin?sent=1", form, rec.Code, rec.Header().Get("Location")) |
| + } |
| + case <-time.After(2 * time.Second): |
| + t.Errorf("POST %v waited on the mailer: the response time says the address is admitted", form) |
| + free() |
| + <-done |
| + } |
| + } |
| + |
| + free() |
| + deadline := time.Now().Add(5 * time.Second) |
| + for len(bm.sent()) < 2 && time.Now().Before(deadline) { |
| + time.Sleep(10 * time.Millisecond) |
| + } |
| + time.Sleep(50 * time.Millisecond) |
| + if got := bm.sent(); len(got) != 2 || got[0] != signedInAddress || got[1] != signedInAddress { |
| + t.Fatalf("mail sent = %v, want two links, both to %s", got, signedInAddress) |
| + } |
| +} |