package calls import ( "bytes" "context" "encoding/base64" "fmt" "log/slog" "net/http" "net/http/httptest" "net/url" "path/filepath" "sort" "strconv" "strings" "sync/atomic" "testing" "time" "amadan.net/rastrillo/rastrillo/db" "gorm.io/gorm" ) // measuredKey marks the context of a request whose statements count. type measuredKey struct{} // countingHandler counts log records, and nothing else. type countingHandler struct{ n *atomic.Int64 } func (h countingHandler) Enabled(context.Context, slog.Level) bool { return true } func (h countingHandler) Handle(context.Context, slog.Record) error { h.n.Add(1); return nil } func (h countingHandler) WithAttrs([]slog.Attr) slog.Handler { return h } func (h countingHandler) WithGroup(string) slog.Handler { return h } // TestMemberAndOutsiderDoTheSameWorkOverBudget is Astra's round-3 probe // on #25 (P1). With a live invitation in the browser and the outsider // budgets spent, membership used to decide what POST /signin did on the // response path: a member wrote a pending row, an outsider wrote a log // line and returned — 0.38–0.65 ms against 76.9–77.9 ms. Every POST now // does the same synchronous work whoever it names: the same database // statements, and no log line at all. The budgets still hold: the // outsider is mailed nothing. func TestMemberAndOutsiderDoTheSameWorkOverBudget(t *testing.T) { var logs atomic.Int64 logger := slog.New(countingHandler{&logs}) d, err := db.Open(filepath.Join(t.TempDir(), "calls.db"), slog.New(slog.DiscardHandler)) if err != nil { t.Fatal(err) } t.Cleanup(func() { d.Close() }) mail := &countingMailer{} mux, a, err := buildForTest(t, d, Config{Origin: keymailOrigin, InstanceKey: "test-only-instance", DEK: base64.StdEncoding.EncodeToString(bytes.Repeat([]byte{3}, 32)), AllowedAddresses: []string{plainMember}, Mailer: mail, Logger: logger}) if err != nil { t.Fatal(err) } _, tok, err := a.store.createMeeting(t.Context(), "x", nil, "person:1") if err != nil { t.Fatal(err) } join := httptest.NewRecorder() mux.ServeHTTP(join, httptest.NewRequest(http.MethodGet, keymailOrigin+"/j/"+tok, nil)) cookies := join.Result().Cookies() if len(cookies) == 0 { t.Fatal("following the invitation set no join cookie") } var statements atomic.Int64 // Only the request's own statements: the mail worker runs beside it // (authorize, after the response) on a context of its own. count := func(tx *gorm.DB) { if tx.Statement.Context != nil && tx.Statement.Context.Value(measuredKey{}) != nil { statements.Add(1) } } cb := a.db.G.Callback() for _, err := range []error{ cb.Query().After("gorm:query").Register("equalwork:query", count), cb.Create().After("gorm:create").Register("equalwork:create", count), cb.Update().After("gorm:update").Register("equalwork:update", count), cb.Delete().After("gorm:delete").Register("equalwork:delete", count), cb.Raw().After("gorm:raw").Register("equalwork:raw", count), cb.Row().After("gorm:row").Register("equalwork:row", count), } { if err != nil { t.Fatal(err) } } ip := 0 post := func(form url.Values) *httptest.ResponseRecorder { ip++ // a fresh client address each time, so rastrillo's per-IP budget stays out of it r := httptest.NewRequest(http.MethodPost, keymailOrigin+"/signin", strings.NewReader(form.Encode())) r.Header.Set("Content-Type", "application/x-www-form-urlencoded") r.Header.Set("Origin", keymailOrigin) r.Header.Set("Sec-Fetch-Site", "same-origin") r.RemoteAddr = "198.51.100." + strconv.Itoa(ip) + ":1234" r = r.WithContext(context.WithValue(r.Context(), measuredKey{}, true)) for _, c := range cookies { r.AddCookie(c) } w := httptest.NewRecorder() mux.ServeHTTP(w, r) return w } // Spend the per-link budget (five) with outsiders, each its own // address so rastrillo's per-address budget stays out of it. for i := 0; i < 6; i++ { post(url.Values{"address": {"spender" + string(rune('a'+i)) + "@else.test"}}) } measure := func(address string) (stmts, lines int64, took time.Duration) { statements.Store(0) logs.Store(0) start := time.Now() rec := post(url.Values{"address": {address}}) took = time.Since(start) if rec.Code != http.StatusSeeOther || rec.Header().Get("Location") != "/signin?sent=1" { t.Fatalf("POST %s: %d %q", address, rec.Code, rec.Header().Get("Location")) } return statements.Load(), logs.Load(), took } ms, ml, _ := measure(plainMember) os, ol, _ := measure("outsider@else.test") if ms != os || ml != ol || ml != 0 { t.Fatalf("member did %d statements and %d log lines, outsider %d and %d: want the same work and no log line on the response path", ms, ml, os, ol) } // Astra's measurement, re-run for the record (not asserted: a // stopwatch in a test is a flake, the statement count is the proof). // Four more of each: rastrillo's per-address budget is five. var mt, ot []time.Duration for i := 0; i < 4; i++ { _, _, d1 := measure(plainMember) _, _, d2 := measure(fmt.Sprintf("outsider%d@else.test", i)) mt, ot = append(mt, d1), append(ot, d2) } median := func(xs []time.Duration) time.Duration { sort.Slice(xs, func(i, j int) bool { return xs[i] < xs[j] }) return xs[len(xs)/2] } t.Logf("median POST /signin over budget: member %v, outsider %v", median(mt), median(ot)) a.signinMail.wait() for _, to := range mail.sent() { if strings.HasPrefix(to, "outsider") { t.Fatalf("an over-budget outsider was mailed (%s): the budgets must still hold", to) } } }