amadan
Send sign-in mail after the response, so its timing says nothing
The same timing split Astra found in Slides (#20, P1): a permitted address waited for SMTP before its ?sent=1 and a stranger did not, so the allowlist was readable off a stopwatch, forced posts included. rauth's Mailer is now a queue in front of the bounded sender: Send queues and returns at once, and one worker asks the allowlist (counting refusals in the log, without the address, as before) and only then sends. Failures, ErrMailBusy included, are logged rather than answered. Bounded (64); Close drains it. SignInForTest and the refusal-log test wait for the queue (FlushSigninMailForTest). TestSigninNeverWaitsForTheMailer blocks the mailer and requires every POST — permitted, stranger, both with force=1 — to answer, then the permitted links to go out. It fails on 96f2e56.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
9 files changed,
+269
−47
internal/calendar/app.go+11 −1internal/calendar/auth.go+3 −4internal/calendar/auth_keymail.go+6 −40internal/calendar/home_router_test.go+1 −0internal/calendar/keymail_signin_test.go+7 −2internal/calendar/signin_mail.go+136 −0internal/calendar/signin_timing_test.go+94 −0internal/calendar/testing.go+10 −0internal/calendartest/delivery_test.go+1 −0
CI passed — run details
CI log
=== vet === go vet ./... go vet -tags browser ./internal/calendartest/ === fmt === === test === go test ./... ? amadan.net/oficina/calendar/cmd/calendar [no test files] ok amadan.net/oficina/calendar/internal/calendar 5.067s ? amadan.net/oficina/calendar/internal/calendar/icons [no test files] ? amadan.net/oficina/calendar/internal/calendar/keymailtest [no test files] ? amadan.net/oficina/calendar/internal/calendar/seal [no test files] ok amadan.net/oficina/calendar/internal/calendartest 2.733s ok amadan.net/oficina/calendar/internal/guardstest 0.051s ? amadan.net/oficina/calendar/scripts/writeestilo [no test files] === migration-check === go tool rastrillo migration check rastrillo migration check: models and migrations agree
diff --git a/internal/calendar/app.go b/internal/calendar/app.go| index 728b30b..c37010c 100644 |
| --- a/internal/calendar/app.go |
| +++ b/internal/calendar/app.go |
| @@ -40,6 +40,8 @@ type App struct { |
| // mailRecorder is non-nil only in development — see buildMailer. |
| mailRecorder *recordingMailer |
| + // signinMail is the queue sign-in links go through (signin_mail.go). |
| + signinMail *mailQueue |
| // auth is held so the harness can mint a session the same way a |
| // real sign-in does, rather than by writing a session row by hand. |
| @@ -140,8 +142,12 @@ func New(cfg Config) (*App, error) { |
| // reminders, booking mail. The recorder stays inside it, so tests |
| // still read what was sent (booking spec §6). |
| mailer = newBoundedSender(mailer) |
| - authPlugin, err := newAuthPlugin(origin, writer, instanceKey, mailer, list, logger, homeSettings != nil) |
| + // Sign-in links alone go through a queue: sent after the response, |
| + // to permitted addresses only (signin_mail.go). Closed by Close. |
| + signinMail := newMailQueue(mailer, list.allows, logger) |
| + authPlugin, err := newAuthPlugin(origin, writer, instanceKey, signinMail, list, logger, homeSettings != nil) |
| if err != nil { |
| + signinMail.close() |
| d.Close() |
| return nil, fmt.Errorf("calendar: wire sign-in: %w", err) |
| } |
| @@ -153,6 +159,7 @@ func New(cfg Config) (*App, error) { |
| logger: logger, |
| store: store, |
| mailRecorder: recorder, |
| + signinMail: signinMail, |
| auth: authPlugin, |
| } |
| h := &handlers{store: store, logger: logger, origin: origin, mailer: mailer, gate: newGate(), viewerFrom: authPlugin.SessionFrom} |
| @@ -215,6 +222,9 @@ func (a *App) Handler() *http.ServeMux { return a.mux } |
| // Close releases the database. Safe to call on a partially built app. |
| func (a *App) Close() error { |
| a.closeOnce.Do(func() { |
| + if a.signinMail != nil { |
| + a.signinMail.close() |
| + } |
| if a.scheduled != nil { |
| a.scheduled.close() |
| } |
diff --git a/internal/calendar/auth.go b/internal/calendar/auth.go| index da93b7c..3b73235 100644 |
| --- a/internal/calendar/auth.go |
| +++ b/internal/calendar/auth.go |
| @@ -15,7 +15,6 @@ import ( |
| "regexp" |
| "strings" |
| "sync" |
| - "sync/atomic" |
| rauth "amadan.net/rastrillo/rastrillo/auth" |
| "amadan.net/rastrillo/rastrillo/mail" |
| @@ -188,8 +187,8 @@ func resolveAllowlist(cfg Config) (allowlist, error) { |
| // rate-limiter budget on the value, so a plugin per request would get a |
| // fresh empty budget every time — no rate limiting at all, silently. |
| // |
| -// Authorize is list.allows as well as admissionMailer. The two defend |
| -// different things: admissionMailer stops the mail going out, Authorize |
| +// Authorize is list.allows as well as mailQueue. The two defend |
| +// different things: mailQueue stops the mail going out, Authorize |
| // stops a session being minted for a non-permitted address, whether |
| // Keymail verified it or a link was somehow minted for it (mailed |
| // before the allowlist changed, say). |
| @@ -204,7 +203,7 @@ func newAuthPlugin(origin string, writer *sql.DB, instanceKey string, mailer mai |
| SignedInPath: signedIn, |
| Origin: origin, |
| InstanceKey: instanceKey, |
| - Mailer: admissionMailer{next: mailer, list: list, logger: logger, refusals: new(atomic.Int64)}, |
| + Mailer: mailer, |
| Authorize: list.allows, |
| Subject: chrome.EmailSubject("Calendar"), |
| Logger: logger, |
diff --git a/internal/calendar/auth_keymail.go b/internal/calendar/auth_keymail.go| index bd037ba..5e04311 100644 |
| --- a/internal/calendar/auth_keymail.go |
| +++ b/internal/calendar/auth_keymail.go |
| @@ -2,14 +2,10 @@ package calendar |
| import ( |
| "bytes" |
| - "context" |
| - "log/slog" |
| "net/http" |
| "strings" |
| - "sync/atomic" |
| "amadan.net/oficina/home/connect" |
| - "amadan.net/rastrillo/rastrillo/mail" |
| ) |
| // beginSignin is POST /signin, in both modes: rauth's Begin for EVERY |
| @@ -28,13 +24,14 @@ import ( |
| // by rauth's Authorize, and its 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 the allowlist holds it, so this app's sending |
| -// identity is no open relay for whatever a stranger types. |
| +// - Any other address is answered ?sent=1, and mailQueue mails the |
| +// link only if the allowlist holds it — after the response, in a |
| +// worker, so not even the response time differs (signin_mail.go) — |
| +// and this app's sending identity is no open relay for whatever a |
| +// stranger types. |
| // |
| // Both kinds of address spend the same rate budgets and parse the same |
| -// way. The one outcome only a permitted address can reach is ?err=1 |
| -// from a send that failed: an operational fault, not an answer. |
| +// way, and a failed send is logged after the response, not answered. |
| // |
| // It used to gate the allowlist in front of Begin and set force=1 on |
| // every permitted request, which kept Keymail out of Calendar |
| @@ -46,37 +43,6 @@ func beginSignin(origin string, begin http.HandlerFunc, render func(http.Respons |
| return connect.OAuthContinuation(origin, begin, render) |
| } |
| -// admissionMailer is the mail half of the allowlist: Begin runs for |
| -// every address, and this is where a non-permitted one is quietly not |
| -// mailed. rauth has stored an expiring token by then; one never |
| -// delivered is never redeemed, and Authorize would refuse it if it |
| -// were. |
| -// |
| -// The refusal is COUNTED IN THE LOG, without the address. The response |
| -// has to stay silent; the log does not. The oracle defence forbids |
| -// telling the CLIENT anything, and the logs rule (AGENTS.md §Logs) |
| -// forbids writing an ADDRESS anywhere, but neither forbids recording |
| -// that a refusal happened. Without this line a correctly-configured |
| -// instance and one whose allowlist is missing the only address anybody |
| -// types are indistinguishable from outside AND from `carlos logs`. |
| -type admissionMailer struct { |
| - next mail.Sender |
| - list allowlist |
| - logger *slog.Logger |
| - refusals *atomic.Int64 |
| -} |
| - |
| -func (m admissionMailer) Send(ctx context.Context, to, subject, body string) error { |
| - if !m.list.allows(to) { |
| - if m.logger != nil { |
| - m.logger.Warn("calendar: signin refused by allowlist", |
| - "stage", "signin.gate", "refusals_since_boot", m.refusals.Add(1)) |
| - } |
| - 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/calendar/home_router_test.go b/internal/calendar/home_router_test.go| index acf56b9..6ba2bd4 100644 |
| --- a/internal/calendar/home_router_test.go |
| +++ b/internal/calendar/home_router_test.go |
| @@ -76,6 +76,7 @@ func homeRedirect(t *testing.T, w *httptest.ResponseRecorder) string { |
| func (f *homeRouterFixture) local(t *testing.T) { |
| t.Helper() |
| homeRedirect(t, f.do("POST", "/signin", "address=alice%40example.test&force=1")) |
| + f.app.signinMail.wait() |
| link := regexp.MustCompile(`https://[^\s<>\"]+/auth/verify\?[^\s<>\"]+`).FindString(f.app.mailRecorder.last()) |
| u, err := url.Parse(link) |
| if err != nil || link == "" { |
diff --git a/internal/calendar/keymail_signin_test.go b/internal/calendar/keymail_signin_test.go| index 06e8013..4c94bb7 100644 |
| --- a/internal/calendar/keymail_signin_test.go |
| +++ b/internal/calendar/keymail_signin_test.go |
| @@ -47,8 +47,9 @@ const ( |
| // countingMailer remembers every address it was asked to write to. |
| type countingMailer struct { |
| - mu sync.Mutex |
| - to []string |
| + mu sync.Mutex |
| + to []string |
| + flush func() // waits for the sign-in mail queue (signin_mail.go) |
| } |
| func (m *countingMailer) Send(_ context.Context, to, _, _ string) error { |
| @@ -59,6 +60,9 @@ func (m *countingMailer) Send(_ context.Context, to, _, _ string) error { |
| } |
| func (m *countingMailer) sent() []string { |
| + if m.flush != nil { |
| + m.flush() |
| + } |
| m.mu.Lock() |
| defer m.mu.Unlock() |
| return append([]string(nil), m.to...) |
| @@ -96,6 +100,7 @@ func newKeymailFixture(t *testing.T, home bool) *keymailFixture { |
| t.Fatal(err) |
| } |
| t.Cleanup(func() { a.Close() }) |
| + mail.flush = a.signinMail.wait |
| return &keymailFixture{app: a, origin: cfg.Origin, mail: mail, km: km} |
| } |
diff --git a/internal/calendar/signin_mail.go b/internal/calendar/signin_mail.go| new file mode 100644 |
| index 0000000..31a12d3 |
| --- /dev/null |
| +++ b/internal/calendar/signin_mail.go |
| @@ -0,0 +1,136 @@ |
| +package calendar |
| + |
| +import ( |
| + "context" |
| + "log/slog" |
| + "sync" |
| + "sync/atomic" |
| + "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 the allowlist and |
| +// only then talks to SMTP. |
| +// |
| +// Both halves are the no-oracle guarantee (beginSignin), 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; Calendar 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. |
| +// |
| +// It sits in front of the bounded sender, so an ErrMailBusy is a log |
| +// line here rather than a ?err=1 only a permitted address could see. |
| +// |
| +// 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 |
| + |
| + refusals atomic.Int64 |
| + |
| + 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("calendar: 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("calendar: 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 on the allowlist: the link rauth stored is never |
| + // delivered, so it is never redeemed. The refusal is COUNTED |
| + // in the log, without the address: the response has to stay |
| + // silent, the log does not (AGENTS.md §Logs). Without this line |
| + // an instance whose allowlist is missing the only address |
| + // anybody types is indistinguishable from a working one. |
| + q.logger.Warn("calendar: signin refused by allowlist", |
| + "stage", "signin.gate", "refusals_since_boot", q.refusals.Add(1)) |
| + 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("calendar: send sign-in link", "err", err) |
| + } |
| +} |
| + |
| +// wait blocks until every link queued so far has been delivered or |
| +// dropped. SignInForTest uses it to read the recorder 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("calendar: sign-in mail still sending at shutdown; abandoned") |
| + } |
| +} |
diff --git a/internal/calendar/signin_timing_test.go b/internal/calendar/signin_timing_test.go| new file mode 100644 |
| index 0000000..b7c4966 |
| --- /dev/null |
| +++ b/internal/calendar/signin_timing_test.go |
| @@ -0,0 +1,94 @@ |
| +package calendar |
| + |
| +import ( |
| + "context" |
| + "io" |
| + "log/slog" |
| + "net/http" |
| + "net/http/httptest" |
| + "net/url" |
| + "path/filepath" |
| + "strings" |
| + "sync" |
| + "testing" |
| + "time" |
| +) |
| + |
| +// 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, a permitted 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 allowlist was readable off a |
| +// stopwatch. With the mailer blocked, every POST — permitted, stranger, |
| +// and both with force=1 — must answer, and the permitted links must |
| +// then go out. |
| +func TestSigninNeverWaitsForTheMailer(t *testing.T) { |
| + bm := &blockingMailer{release: make(chan struct{})} |
| + a, err := New(Config{DBPath: filepath.Join(t.TempDir(), "calendar.db"), Env: "development", Origin: TestOrigin, |
| + AllowedAddresses: plainMember, Mailer: bm, Logger: slog.New(slog.NewTextHandler(io.Discard, nil))}) |
| + if err != nil { |
| + t.Fatal(err) |
| + } |
| + t.Cleanup(func() { a.Close() }) |
| + var once sync.Once |
| + free := func() { once.Do(func() { close(bm.release) }) } |
| + t.Cleanup(free) // runs before Close, which drains the queue |
| + |
| + for _, form := range []url.Values{ |
| + {"address": {plainMember}}, |
| + {"address": {"someone@else.test"}}, |
| + {"address": {plainMember}, "force": {"1"}}, |
| + {"address": {"someone@else.test"}, "force": {"1"}}, |
| + } { |
| + done := make(chan *httptest.ResponseRecorder, 1) |
| + go func() { |
| + r := httptest.NewRequest(http.MethodPost, TestOrigin+"/signin", strings.NewReader(form.Encode())) |
| + r.Header.Set("Content-Type", "application/x-www-form-urlencoded") |
| + r.Header.Set("Origin", TestOrigin) |
| + w := httptest.NewRecorder() |
| + a.mux.ServeHTTP(w, r) |
| + done <- w |
| + }() |
| + 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 permitted", 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] != plainMember || got[1] != plainMember { |
| + t.Fatalf("mail sent = %v, want two links, both to %s", got, plainMember) |
| + } |
| +} |
diff --git a/internal/calendar/testing.go b/internal/calendar/testing.go| index 02f48ef..28bfd08 100644 |
| --- a/internal/calendar/testing.go |
| +++ b/internal/calendar/testing.go |
| @@ -75,6 +75,8 @@ func (a *App) SignInForTest(t TB, address string) *http.Cookie { |
| req.Header.Set("Content-Type", "application/x-www-form-urlencoded") |
| req.Header.Set("Origin", TestOrigin) |
| a.mux.ServeHTTP(httptest.NewRecorder(), req) |
| + // The link is sent after the response (signin_mail.go). |
| + a.signinMail.wait() |
| link := magicLinkPattern.FindString(a.mailRecorder.last()) |
| if link == "" { |
| @@ -162,6 +164,7 @@ func (a *App) LastMailForTest() (string, error) { |
| if a.mailRecorder == nil { |
| return "", fmt.Errorf("calendar: no mail recorder (Env is %q, not \"development\")", a.cfg.Env) |
| } |
| + a.signinMail.wait() |
| return a.mailRecorder.last(), nil |
| } |
| @@ -213,3 +216,10 @@ func (a *App) SetAfterSlotCheckForTest(f func()) { a.store.afterSlotCheckForTest |
| func (a *App) TrySendNowForTest(bookingID int64) bool { |
| return a.h.trySendNow(context.Background(), bookingID, time.Now()) |
| } |
| + |
| +// FlushSigninMailForTest waits until every sign-in link queued so far |
| +// has been sent or refused. Links go out after the response |
| +// (signin_mail.go), and so does the refusal's log line. |
| +func (a *App) FlushSigninMailForTest() { |
| + a.signinMail.wait() |
| +} |
diff --git a/internal/calendartest/delivery_test.go b/internal/calendartest/delivery_test.go| index 6053699..a98a5d1 100644 |
| --- a/internal/calendartest/delivery_test.go |
| +++ b/internal/calendartest/delivery_test.go |
| @@ -257,6 +257,7 @@ func TestARefusedSignInIsCountedInTheLog(t *testing.T) { |
| t.Cleanup(func() { app.Close() }) |
| post(t, app.Handler(), "/signin", url.Values{"address": {"stranger@example.com"}}) |
| + app.FlushSigninMailForTest() // refusals are logged after the response |
| out := log.String() |
| if !strings.Contains(out, "signin refused by allowlist") { |