amadan

oficina / calendar Public

delivery: make a refused sign-in visible, and stop one bad address blocking every reminder

Found by a real failure: a sign-in for an address that was not on
CALENDAR_ALLOWED_ADDRESSES sent no mail and said nothing about it,
anywhere. The response is byte-identical to a real send on purpose
(anti-enumeration) and AGENTS.md forbids an address in a log line, so
between them the app had no way at all to report a misconfigured
allowlist. Somebody sat waiting for a link that was never going to
arrive, and the only diagnostic left was reading the env var by eye.

Five fixes, each with a test that fails without it:

1. gateBegin now logs a COUNTED refusal with no address. The response
   stays byte-identical; the log stops being silent.

2. resolveAllowlist refuses to boot on an entry with no "@" in it.
   Splitting on "," alone turned "a@x.com;b@y.com" into one entry that
   is nobody's address — a non-empty allowlist, a healthy-looking boot,
   and nobody admitted. The same "quietly admits nobody" state the
   empty check already existed to prevent, reached another way.

3. FailReminder REFRESHES the claim instead of clearing it. Clearing it
   put the failing row straight back at the head of ClaimDueReminder's
   "ORDER BY due_at ASC", so the next claim in the same pass returned
   the same row, the drain's seen-guard tripped, and the pass returned
   with every reminder behind it unsent. One bounced mailbox delayed
   the whole team's reminders by up to ~30 hours on a 6h tick, and the
   log blamed a double claim rather than the address.

4. Giving up on a rule now reschedules it. The dead-letter marker moved
   off the queue row and onto the rule (Reminder.UndeliverableAt),
   because one row per rule means the marker and the next occurrence
   want the same row. Previously a daily standup that hit a relay
   outage lost its reminders permanently and silently.

5. scrub() takes addresses out of logged errors. The logs rule was
   being broken on every failed send, and not by our own formatting:
   rastrillo's mailer puts the recipient into its error string and we
   logged that verbatim.

Also fixes a latent test rot found on the way: occurrence_test.go wrote
its dates as literals matching the day they were authored. A chip's
label is tense-dependent — the start time ahead of time, "ended <end>"
afterwards — so those assertions passed all morning and failed every
afternoon, and would have failed outright from the next day. They are
now relative to today and always in the future.

Reported by a Fable audit of the whole mail path; findings 1-4 are its
numbering, verified here against the code before being acted on.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01QG3FX6qzynri8yTgMUm7q7
Paul Campbell pushed by paul@keymail.dev 0cb448446af805c195032cf24d75e97f3ed4835c parent 12173e5
12 files changed, +517 −46
  • .gitignore +3 −0
  • internal/calendar/auth.go +40 −1
  • internal/calendar/handlers_jobs.go +8 −6
  • internal/calendar/logsafe.go +40 −0
  • internal/calendar/logsafe_test.go +44 −0
  • internal/calendar/migrations/0003_alter_reminders.sql +2 −0
  • internal/calendar/migrations/schema.sql +1 −1
  • internal/calendar/models_event.go +14 −0
  • internal/calendar/routes.go +7 −1
  • internal/calendar/store_drain.go +49 −15
  • internal/calendartest/delivery_test.go +266 −0
  • internal/calendartest/occurrence_test.go +43 −22
diff --git a/.gitignore b/.gitignore
index 074bc7e..1188c78 100644
--- a/.gitignore
+++ b/.gitignore
@@ -38,3 +38,6 @@
.DS_Store
Thumbs.db
+
+# The JS test harness (Playwright) is installed, never vendored.
+node_modules/
diff --git a/internal/calendar/auth.go b/internal/calendar/auth.go
index f738551..a78eee1 100644
--- a/internal/calendar/auth.go
+++ b/internal/calendar/auth.go
@@ -21,6 +21,7 @@ import (
"regexp"
"strings"
"sync"
+ "sync/atomic"
rauth "github.com/carlosframework/rastrillo/auth"
"github.com/carlosframework/rastrillo/mail"
@@ -160,6 +161,23 @@ func resolveAllowlist(cfg Config) (allowlist, error) {
if addr == "" {
continue
}
+ // Every entry must look like an address, because the separator
+ // is the one thing nobody checks. Split on "," alone turns
+ // "a@x.com;b@y.com" — or a space- or newline-separated list —
+ // into ONE entry that is nobody's address, len(addrs) > 0, and
+ // a boot that succeeds into precisely the "quietly admits
+ // nobody" state the refusal below exists to prevent. The
+ // instance then looks entirely healthy and no link ever
+ // arrives, which is the failure this app has already had once.
+ //
+ // Refusing at boot rather than dropping the bad entry: dropping
+ // it would admit whoever parsed cleanly and silently lock out
+ // the rest, which is a worse shape of the same bug.
+ if !strings.Contains(addr, "@") {
+ return allowlist{}, fmt.Errorf(
+ "calendar: $CALENDAR_ALLOWED_ADDRESSES has an entry with no %q in it — the list is comma-separated, and a %q or a space is not a separator; refusing to start rather than admit nobody",
+ "@", ";")
+ }
addrs[addr] = struct{}{}
}
if len(addrs) > 0 {
@@ -195,7 +213,24 @@ func resolveAllowlist(cfg Config) (allowlist, error) {
// wants that ceremony anyway (see the package comment), so forcing the
// plain-link path here makes it a guarantee for every request this
// handler forwards rather than only for the ones built by our own form.
-func gateBegin(next http.HandlerFunc, list allowlist, signinPath string) http.HandlerFunc {
+// The refusal is COUNTED IN THE LOG, without the address.
+//
+// The response has to stay silent; the log does not, and the two rules
+// that made this route undiagnosable were pulling in the same
+// direction only by accident. The oracle defence forbids telling the
+// CLIENT anything, and the logs rule (AGENTS.md §Logs) forbids writing
+// an ADDRESS anywhere. 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`: the operator's
+// single remaining move is to read the environment variable and compare
+// it by eye, which is how this was actually found after somebody sat
+// waiting for a link that was never going to arrive.
+//
+// The count is the whole payload. "signin refused" with a running total
+// is enough to answer "is this instance refusing everything?", which is
+// the only question the log needs to answer, and it names nobody.
+func gateBegin(next http.HandlerFunc, list allowlist, signinPath string, logger *slog.Logger, refusals *atomic.Int64) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
// A malformed body reads back as address == "" below, which is
// never on a non-empty allowlist — the same answer Begin would
@@ -209,6 +244,10 @@ func gateBegin(next http.HandlerFunc, list allowlist, signinPath string) http.Ha
next(w, r)
return
}
+ if logger != nil {
+ logger.Warn("calendar: signin refused by allowlist",
+ "stage", "signin.gate", "refusals_since_boot", refusals.Add(1))
+ }
http.Redirect(w, r, signinPath+"?sent=1", http.StatusSeeOther)
}
}
diff --git a/internal/calendar/handlers_jobs.go b/internal/calendar/handlers_jobs.go
index 4a010db..77f7873 100644
--- a/internal/calendar/handlers_jobs.go
+++ b/internal/calendar/handlers_jobs.go
@@ -30,7 +30,7 @@ func (h *handlers) drainReminders(w http.ResponseWriter, r *http.Request) {
if err != nil {
// 5xx so the platform retries. The occurrence key makes a
// retry safe.
- h.logger.Error("calendar: drain reminders", "err", err)
+ h.logger.Error("calendar: drain reminders", "stage", "reminders.drain", "err", scrubErr(err))
http.Error(w, "retry", http.StatusInternalServerError)
return
}
@@ -77,8 +77,9 @@ func (h *handlers) drain(ctx context.Context, now time.Time) (int, error) {
// Leave it claimed; the lease expires and a later pass
// retries. Recording the attempt is what stops a
// permanently undeliverable address being retried forever.
- h.logger.Error("calendar: send reminder", "err", err, "attempts", due.Queue.Attempts)
- if err := h.store.FailReminder(ctx, due.Queue.ID); err != nil {
+ h.logger.Error("calendar: send reminder", "stage", "reminders.send",
+ "err", scrubErr(err), "attempts", due.Queue.Attempts)
+ if err := h.store.FailReminder(ctx, due.Queue.ID, due.StartUTC); err != nil {
return sent, err
}
continue
@@ -166,12 +167,13 @@ func (h *handlers) DrainOnRequest(ctx context.Context) {
}
now := time.Now()
if err := h.sendReminder(ctx, due, now); err != nil {
- h.logger.Error("calendar: opportunistic reminder", "err", err)
- _ = h.store.FailReminder(ctx, due.Queue.ID)
+ h.logger.Error("calendar: opportunistic reminder", "stage", "reminders.send",
+ "err", scrubErr(err))
+ _ = h.store.FailReminder(ctx, due.Queue.ID, due.StartUTC)
return
}
if err := h.store.MarkReminderSent(ctx, due.Queue.ID, now.Unix()); err != nil {
- h.logger.Error("calendar: mark reminder sent", "err", err)
+ h.logger.Error("calendar: mark reminder sent", "stage", "reminders.mark", "err", scrubErr(err))
return
}
_ = h.store.RescheduleAfterFiring(ctx, due.Queue.ReminderID, due.StartUTC)
diff --git a/internal/calendar/logsafe.go b/internal/calendar/logsafe.go
new file mode 100644
index 0000000..3431429
--- /dev/null
+++ b/internal/calendar/logsafe.go
@@ -0,0 +1,40 @@
+package calendar
+
+import "regexp"
+
+// addressPattern matches an email address well enough to redact one.
+//
+// Deliberately loose. A redactor that misses is worse than one that
+// over-matches, so this takes anything shaped like local@domain.tld
+// rather than trying to implement RFC 5322 — the cost of a false
+// positive here is a log line that says [address] where it could have
+// said a hostname, and the cost of a false negative is a real person's
+// address in platform-held storage we cannot go back and grep.
+var addressPattern = regexp.MustCompile(`[a-zA-Z0-9._%+\-]+@[a-zA-Z0-9.\-]+\.[a-zA-Z]{2,}`)
+
+// scrub removes email addresses from a string bound for the log.
+//
+// AGENTS.md §Logs: no title, place, note or address in any log line,
+// error string or metric label. `carlos logs` is platform-held storage
+// we cannot grep afterwards, so the rule has to be applied BEFORE the
+// line is written, not apologised for later.
+//
+// This exists because the rule was being broken on every failed send
+// and not by this app's own code: rastrillo's mailer formats the
+// recipient into its error ("send to %s: ..."), and logging that error
+// verbatim — which is the obvious, careful-looking thing to do — put
+// the address straight into the log. An error from a dependency is
+// still an error string we are writing.
+func scrub(s string) string {
+ return addressPattern.ReplaceAllString(s, "[address]")
+}
+
+// scrubErr is scrub for an error, returning a string rather than an
+// error so a caller cannot accidentally log the original by wrapping
+// the result.
+func scrubErr(err error) string {
+ if err == nil {
+ return ""
+ }
+ return scrub(err.Error())
+}
diff --git a/internal/calendar/logsafe_test.go b/internal/calendar/logsafe_test.go
new file mode 100644
index 0000000..e0c4606
--- /dev/null
+++ b/internal/calendar/logsafe_test.go
@@ -0,0 +1,44 @@
+package calendar
+
+import (
+ "errors"
+ "strings"
+ "testing"
+)
+
+// The logs rule is absolute, and the thing that broke it was not this
+// app's own formatting: rastrillo's mailer puts the recipient into its
+// error, and logging that error verbatim is the obvious careful thing
+// to do. scrub is what makes "log the error" safe.
+func TestScrubTakesAddressesOutOfLogLines(t *testing.T) {
+ cases := []struct {
+ in string
+ want string
+ }{
+ {"send to paul@example.com: connection refused",
+ "send to [address]: connection refused"},
+ {"smtp: 550 5.1.1 <someone.else+tag@sub.example.co.uk> unknown",
+ "smtp: 550 5.1.1 <[address]> unknown"},
+ {"two: a@x.com and b@y.org", "two: [address] and [address]"},
+ {"nothing to redact here", "nothing to redact here"},
+ }
+ for _, c := range cases {
+ if got := scrub(c.in); got != c.want {
+ t.Errorf("scrub(%q) = %q, want %q", c.in, got, c.want)
+ }
+ }
+}
+
+func TestScrubErrHandlesNil(t *testing.T) {
+ if got := scrubErr(nil); got != "" {
+ t.Errorf("scrubErr(nil) = %q, want empty", got)
+ }
+ got := scrubErr(errors.New("dial mail.example.com: no route for bob@example.com"))
+ if strings.Contains(got, "bob@example.com") {
+ t.Errorf("scrubErr left the address in: %q", got)
+ }
+ // The parts that make an error useful must survive.
+ if !strings.Contains(got, "no route") {
+ t.Errorf("scrubErr threw away the diagnosis: %q", got)
+ }
+}
diff --git a/internal/calendar/migrations/0003_alter_reminders.sql b/internal/calendar/migrations/0003_alter_reminders.sql
new file mode 100644
index 0000000..5bd6d65
--- /dev/null
+++ b/internal/calendar/migrations/0003_alter_reminders.sql
@@ -0,0 +1,2 @@
+ALTER TABLE `reminders` ADD `undeliverable_at` integer;
+
diff --git a/internal/calendar/migrations/schema.sql b/internal/calendar/migrations/schema.sql
index 8de22b4..f30b582 100644
--- a/internal/calendar/migrations/schema.sql
+++ b/internal/calendar/migrations/schema.sql
@@ -15,7 +15,7 @@ CREATE TABLE `people` (`id` integer PRIMARY KEY AUTOINCREMENT,`address` text NOT
CREATE TABLE `reminder_queues` (`id` integer PRIMARY KEY AUTOINCREMENT,`reminder_id` integer NOT NULL,`occurrence_key` text NOT NULL,`due_at` integer NOT NULL,`claimed_at` integer,`fired_at` integer,`attempts` integer NOT NULL,`late_by_sec` integer NOT NULL);
-CREATE TABLE `reminders` (`id` integer PRIMARY KEY AUTOINCREMENT,`event_id` integer NOT NULL,`person_id` integer NOT NULL,`offset_min` integer NOT NULL,`channel` text NOT NULL,`created_at` datetime NOT NULL);
+CREATE TABLE `reminders` (`id` integer PRIMARY KEY AUTOINCREMENT,`event_id` integer NOT NULL,`person_id` integer NOT NULL,`offset_min` integer NOT NULL,`channel` text NOT NULL,`created_at` datetime NOT NULL, `undeliverable_at` integer);
CREATE INDEX `idx_calendars_archived_at` ON `calendars`(`archived_at`);
diff --git a/internal/calendar/models_event.go b/internal/calendar/models_event.go
index feabd0f..49740b8 100644
--- a/internal/calendar/models_event.go
+++ b/internal/calendar/models_event.go
@@ -166,6 +166,20 @@ type Reminder struct {
// web push arrives as a value rather than a schema change.
Channel string `gorm:"column:channel;not null"`
+ // UndeliverableAt records that this rule gave up on an occurrence
+ // after MaxReminderAttempts, and it lives HERE rather than on the
+ // queue row because the queue row has to move on.
+ //
+ // One row per rule means the dead-letter marker and the next
+ // occurrence want the same row, and only one of them can have it.
+ // Keeping the marker there is what made a recurring reminder die
+ // permanently the first time a relay was down: the row stayed
+ // fired, nothing queued the next occurrence, and a daily standup
+ // silently lost its reminders forever. Recording it on the rule
+ // instead lets the queue row be rescheduled while the failure stays
+ // visible on the settings page.
+ UndeliverableAt *int64 `gorm:"column:undeliverable_at"`
+
CreatedAt time.Time `gorm:"column:created_at;not null"`
}
diff --git a/internal/calendar/routes.go b/internal/calendar/routes.go
index d05290c..5d35426 100644
--- a/internal/calendar/routes.go
+++ b/internal/calendar/routes.go
@@ -2,6 +2,7 @@ package calendar
import (
"net/http"
+ "sync/atomic"
"github.com/go-chi/chi/v5"
@@ -28,7 +29,12 @@ func (a *App) routes(h *handlers, authPlugin *rauth.Auth, list allowlist, origin
// Signed-out.
r.Get("/signin", h.signin)
- r.Post("/signin", gateBegin(authPlugin.Begin, list, "/signin"))
+ // One counter for the life of the router, so the log line can say
+ // how many refusals this boot has seen rather than only that one
+ // happened. routes runs once per App, so the closure below is the
+ // only holder and no reset can race it.
+ var refusals atomic.Int64
+ r.Post("/signin", gateBegin(authPlugin.Begin, list, "/signin", a.logger, &refusals))
r.Get("/auth/callback", authPlugin.Callback)
r.Get("/auth/verify", authPlugin.Verify)
r.Post("/signout", authPlugin.Signout)
diff --git a/internal/calendar/store_drain.go b/internal/calendar/store_drain.go
index e3b9d96..b5d8a64 100644
--- a/internal/calendar/store_drain.go
+++ b/internal/calendar/store_drain.go
@@ -158,35 +158,69 @@ func (s *Store) MarkReminderSent(ctx context.Context, queueID, now int64) error
const MaxReminderAttempts = 5
// FailReminder records an attempt and gives up after enough of them.
-func (s *Store) FailReminder(ctx context.Context, queueID int64) error {
+//
+// occurrenceStartUTC is the start of the occurrence that just failed,
+// needed only on the giving-up path so the NEXT one can be queued.
+//
+// Two things here are deliberate and both were bugs:
+//
+// The claim is REFRESHED rather than cleared. Clearing it put the row
+// straight back at the head of ClaimDueReminder's `ORDER BY due_at
+// ASC`, so the very next claim in the same pass returned the same row,
+// the drain's `seen` guard tripped, and the pass returned early — with
+// every other due reminder still unsent. One undeliverable address
+// therefore held up the whole team's reminders, for up to ~30 hours on
+// a 6h tick, and the log line blamed a double claim rather than the
+// address. Leaving the lease in place makes the five-minute claim do
+// the backoff it was already written to do, and the pass moves on to
+// the next person's reminder.
+//
+// Giving up RESCHEDULES the rule. See Reminder.UndeliverableAt: the
+// marker lives on the rule so the queue row is free to move on. For a
+// single event there is no next occurrence and rescheduleAfter deletes
+// the row, which is the same end state as before.
+func (s *Store) FailReminder(ctx context.Context, queueID, occurrenceStartUTC int64) error {
var q ReminderQueue
if err := s.g.WithContext(ctx).First(&q, queueID).Error; err != nil {
return fmt.Errorf("calendar: read queue row: %w", err)
}
+ now := time.Now().Unix()
attempts := q.Attempts + 1
- updates := map[string]any{"attempts": attempts, "claimed_at": nil}
- if attempts >= MaxReminderAttempts {
- // Marked fired without having been sent: the alternative is a
- // row that is retried at every wake for the rest of the
- // instance's life. The settings page lists these as
- // undeliverable, so it is visible rather than silent.
- updates["fired_at"] = time.Now().Unix()
+
+ if attempts < MaxReminderAttempts {
+ err := s.g.WithContext(ctx).Model(&ReminderQueue{}).
+ Where("id = ?", queueID).
+ Updates(map[string]any{"attempts": attempts, "claimed_at": now}).Error
+ if err != nil {
+ return fmt.Errorf("calendar: record reminder failure: %w", err)
+ }
+ return nil
}
- err := s.g.WithContext(ctx).Model(&ReminderQueue{}).
- Where("id = ?", queueID).Updates(updates).Error
- if err != nil {
+
+ // Given up on. Record it against the rule, where it survives the
+ // queue row being reused, then let the series carry on.
+ if err := s.g.WithContext(ctx).Model(&Reminder{}).
+ Where("id = ?", q.ReminderID).
+ Update("undeliverable_at", now).Error; err != nil {
+ return fmt.Errorf("calendar: mark reminder undeliverable: %w", err)
+ }
+ if err := s.g.WithContext(ctx).Model(&ReminderQueue{}).
+ Where("id = ?", queueID).
+ Updates(map[string]any{"attempts": attempts, "claimed_at": now}).Error; err != nil {
return fmt.Errorf("calendar: record reminder failure: %w", err)
}
- return nil
+ return s.rescheduleAfter(ctx, q.ReminderID, occurrenceStartUTC)
}
// UndeliverableReminders lists the ones that gave up, for the settings
// page.
+// Counted off the RULE, not the queue row. The queue row is rescheduled
+// the moment a rule gives up, so its attempts counter is reset and would
+// report nothing was ever undeliverable.
func (s *Store) UndeliverableReminders(ctx context.Context, personID int64) (int64, error) {
var n int64
- err := s.g.WithContext(ctx).Model(&ReminderQueue{}).
- Joins("JOIN reminders ON reminders.id = reminder_queues.reminder_id").
- Where("reminders.person_id = ? AND reminder_queues.attempts >= ?", personID, MaxReminderAttempts).
+ err := s.g.WithContext(ctx).Model(&Reminder{}).
+ Where("person_id = ? AND undeliverable_at IS NOT NULL", personID).
Count(&n).Error
if err != nil {
return 0, fmt.Errorf("calendar: count undeliverable: %w", err)
diff --git a/internal/calendartest/delivery_test.go b/internal/calendartest/delivery_test.go
new file mode 100644
index 0000000..30507ac
--- /dev/null
+++ b/internal/calendartest/delivery_test.go
@@ -0,0 +1,266 @@
+package calendartest
+
+import (
+ "context"
+ "fmt"
+ "io"
+ "log/slog"
+ "net/http"
+ "net/http/httptest"
+ "net/url"
+ "path/filepath"
+ "strings"
+ "sync"
+ "testing"
+ "time"
+
+ calendar "amadan.net/oficina/calendar/internal/calendar"
+)
+
+// pickyMailer delivers everything except messages whose body contains
+// refuse, and remembers what it actually delivered.
+//
+// A recorder alone cannot answer these tests: the app's own development
+// recorder stores the body BEFORE forwarding, so it holds the last
+// message ATTEMPTED rather than the last one delivered — which is
+// exactly the distinction a test about failed sends has to make.
+type pickyMailer struct {
+ refuse string
+
+ mu sync.Mutex
+ delivered []string
+ attempts int
+}
+
+func (m *pickyMailer) Send(_ context.Context, _, subject, body string) error {
+ m.mu.Lock()
+ defer m.mu.Unlock()
+ m.attempts++
+ if m.refuse != "" && strings.Contains(subject+body, m.refuse) {
+ // Shaped like the real thing: rastrillo's mailer formats the
+ // recipient into its error, which is what scrub exists for.
+ return fmt.Errorf("send to nobody@example.com: connection refused")
+ }
+ m.delivered = append(m.delivered, subject+"\n"+body)
+ return nil
+}
+
+func (m *pickyMailer) deliveredContaining(needle string) bool {
+ m.mu.Lock()
+ defer m.mu.Unlock()
+ for _, d := range m.delivered {
+ if strings.Contains(d, needle) {
+ return true
+ }
+ }
+ return false
+}
+
+// newAppWithMailer builds an app whose outgoing mail goes through
+// mailer. Env stays "development", so the sign-in recorder still works
+// and SignInForTest can drive a real sign-in.
+func newAppWithMailer(t *testing.T, mailer *pickyMailer) *calendar.App {
+ t.Helper()
+ app, err := calendar.New(calendar.Config{
+ DBPath: filepath.Join(t.TempDir(), "calendar.db"),
+ Env: "development",
+ Origin: testOrigin,
+ Mailer: mailer,
+ Logger: slog.New(slog.NewTextHandler(io.Discard, nil)),
+ })
+ if err != nil {
+ t.Fatalf("calendar.New: %v", err)
+ }
+ t.Cleanup(func() { app.Close() })
+ return app
+}
+
+func tick(t *testing.T, h http.Handler) *httptest.ResponseRecorder {
+ t.Helper()
+ req := httptest.NewRequest(http.MethodPost, "/jobs/reminders", nil)
+ req.Header.Set("Authorization", "Bearer test-token")
+ rec := httptest.NewRecorder()
+ h.ServeHTTP(rec, req)
+ return rec
+}
+
+// ONE undeliverable address must not hold up everybody else's
+// reminders.
+//
+// The bug this pins: FailReminder used to CLEAR claimed_at, which put
+// the failing row straight back at the head of ClaimDueReminder's
+// "ORDER BY due_at ASC". The next claim in the same pass returned the
+// same row, the drain's seen-guard tripped, and the pass returned with
+// every reminder behind it unsent — so one bounced mailbox silently
+// delayed the whole team's reminders until the next tick, and the log
+// blamed a double claim rather than the address.
+func TestOneUndeliverableReminderDoesNotBlockTheRest(t *testing.T) {
+ t.Setenv("CARLOS_ADMIN_TOKEN", "test-token")
+
+ mailer := &pickyMailer{refuse: "Wedged"}
+ app := newAppWithMailer(t, mailer)
+ session := app.SignInForTest(t, "someone@example.com")
+ h := app.Handler()
+
+ // Both already inside their ten-minute default warning, and the
+ // wedged one is due FIRST so it is claimed first. UTC because that
+ // is the test person's zone.
+ now := time.Now().UTC()
+ for _, e := range []struct {
+ title string
+ at time.Time
+ }{
+ {"Wedged meeting", now.Add(1 * time.Minute)},
+ {"Meeting behind it", now.Add(3 * time.Minute)},
+ } {
+ createEvent(t, h, session, url.Values{
+ "title": {e.title},
+ "start": {e.at.Format("2006-01-02T15:04")},
+ "end": {e.at.Add(15 * time.Minute).Format("2006-01-02T15:04")},
+ "kind": {"meeting"},
+ "status": {"confirmed"},
+ "repeat": {"none"},
+ })
+ }
+
+ if rec := tick(t, h); rec.Code != http.StatusNoContent {
+ t.Fatalf("drain: status %d, want 204\n%s", rec.Code, rec.Body.String())
+ }
+
+ if !mailer.deliveredContaining("Meeting behind it") {
+ t.Error("the reminder behind an undeliverable one was never sent — " +
+ "one bad address is blocking the queue")
+ }
+ if mailer.deliveredContaining("Wedged meeting") {
+ t.Error("the mailer reported refusing this message but it was recorded as delivered")
+ }
+}
+
+// Giving up on a recurring reminder must not kill the series.
+//
+// The bug this pins: on the final attempt FailReminder marked the queue
+// row fired and stopped. Nothing queued the next occurrence, NextDueAt
+// ignored a fired row, and a daily standup that hit a relay outage lost
+// its reminders permanently and silently. The undeliverable fact now
+// lives on the RULE (Reminder.UndeliverableAt) so the queue row is free
+// to move on.
+func TestGivingUpOnARecurringReminderKeepsTheSeriesAlive(t *testing.T) {
+ t.Setenv("CARLOS_ADMIN_TOKEN", "test-token")
+
+ mailer := &pickyMailer{refuse: "Doomed"}
+ app := newAppWithMailer(t, mailer)
+ session := app.SignInForTest(t, "someone@example.com")
+ h := app.Handler()
+
+ start := time.Now().UTC().Add(1 * time.Minute)
+ createEvent(t, h, session, url.Values{
+ "title": {"Doomed standup"},
+ "start": {start.Format("2006-01-02T15:04")},
+ "end": {start.Add(15 * time.Minute).Format("2006-01-02T15:04")},
+ "kind": {"meeting"},
+ "status": {"confirmed"},
+ "repeat": {"daily"},
+ })
+
+ // Stand the row up on its LAST attempt rather than waiting out five
+ // five-minute claim leases. The lease is the backoff the fix above
+ // introduced, so burning the attempts honestly would take ~25
+ // minutes of wall clock.
+ db := app.DBForTest()
+ if _, err := db.Exec(
+ `UPDATE reminder_queues SET attempts = ?, claimed_at = NULL`,
+ calendar.MaxReminderAttempts-1); err != nil {
+ t.Fatalf("priming the queue row: %v", err)
+ }
+
+ if rec := tick(t, h); rec.Code != http.StatusNoContent {
+ t.Fatalf("drain: status %d, want 204", rec.Code)
+ }
+
+ // The series is still scheduled: the next occurrence is queued,
+ // roughly a day out.
+ due := app.NextDue()
+ if due.IsZero() {
+ t.Fatal("giving up on one occurrence unqueued the whole series — " +
+ "this rule will never remind anybody again")
+ }
+ if until := time.Until(due); until < 20*time.Hour || until > 26*time.Hour {
+ t.Errorf("the requeued reminder is %v away, want about a day", until)
+ }
+
+ // And the failure is still visible rather than erased by the
+ // reschedule.
+ var n int
+ if err := db.QueryRow(
+ `SELECT COUNT(*) FROM reminders WHERE undeliverable_at IS NOT NULL`).Scan(&n); err != nil {
+ t.Fatalf("counting undeliverable rules: %v", err)
+ }
+ if n != 1 {
+ t.Errorf("%d rules marked undeliverable, want 1 — "+
+ "rescheduling erased the record of the failure", n)
+ }
+}
+
+// An address that is not on the allowlist must leave a trace in the
+// LOG, even though it deliberately leaves none in the response.
+//
+// The two rules that meet here were pulling the same way by accident:
+// the response must be byte-identical to a real send (anti-enumeration)
+// and no address may be written to a log line (AGENTS.md §Logs). Obeying
+// both by staying completely silent made a misconfigured allowlist
+// undiagnosable from outside AND from `carlos logs` — which is how a
+// real person came to sit waiting for a link that was never sent.
+func TestARefusedSignInIsCountedInTheLog(t *testing.T) {
+ var log strings.Builder
+ app, err := calendar.New(calendar.Config{
+ DBPath: filepath.Join(t.TempDir(), "calendar.db"),
+ Env: "development",
+ Origin: testOrigin,
+ AllowedAddresses: "allowed@example.com",
+ Logger: slog.New(slog.NewTextHandler(&log, nil)),
+ })
+ if err != nil {
+ t.Fatalf("calendar.New: %v", err)
+ }
+ t.Cleanup(func() { app.Close() })
+
+ post(t, app.Handler(), "/signin", url.Values{"address": {"stranger@example.com"}})
+
+ out := log.String()
+ if !strings.Contains(out, "signin refused by allowlist") {
+ t.Errorf("a refused sign-in left no trace in the log:\n%s", out)
+ }
+ // The trace must not be the thing the logs rule forbids.
+ if strings.Contains(out, "stranger@example.com") {
+ t.Errorf("the refusal log names the address, which AGENTS.md forbids:\n%s", out)
+ }
+}
+
+// A list written with the wrong separator must refuse to boot rather
+// than admit nobody.
+//
+// Splitting on "," alone turns "a@x.com;b@y.com" into ONE entry that is
+// nobody's address, which is a non-empty allowlist and therefore a
+// successful boot — the exact "quietly admits nobody" state the empty
+// check was written to prevent, reached by a different route.
+func TestAnAllowlistWithTheWrongSeparatorRefusesToStart(t *testing.T) {
+ for _, list := range []string{
+ "a@example.com;b@example.com",
+ "a@example.com b@example.com",
+ "nonsense",
+ } {
+ _, err := calendar.New(calendar.Config{
+ DBPath: filepath.Join(t.TempDir(), "calendar.db"),
+ Env: "production",
+ Origin: testOrigin,
+ InstanceKey: "test-instance-key",
+ Mailer: &pickyMailer{},
+ AllowedAddresses: list,
+ Logger: slog.New(slog.NewTextHandler(io.Discard, nil)),
+ })
+ if err == nil {
+ t.Errorf("$CALENDAR_ALLOWED_ADDRESSES = %q booted successfully; "+
+ "it admits nobody and looks perfectly healthy", list)
+ }
+ }
+}
diff --git a/internal/calendartest/occurrence_test.go b/internal/calendartest/occurrence_test.go
index 7ebc219..ee61a0f 100644
--- a/internal/calendartest/occurrence_test.go
+++ b/internal/calendartest/occurrence_test.go
@@ -5,8 +5,29 @@ import (
"net/url"
"strings"
"testing"
+ "time"
)
+// testDay and testAt anchor these tests to dates that are always in the
+// FUTURE, and that is the whole point of them.
+//
+// The dates here used to be written out literally. That made the suite
+// rot on a clock: a chip's own label is tense-dependent — chipFor prints
+// the start time for an event still to come and "ended <end>" for one
+// already over (viewdata.go) — so an assertion that a day still shows
+// its 09:30 occurrence passed all morning and failed every afternoon,
+// and would have failed outright from the day after the literals were
+// written. It was found exactly that way, at 18:07 on the day the
+// literals named.
+//
+// The person these tests sign in as is in UTC, so UTC is the zone the
+// submitted wall time is read in.
+func testDay(n int) string {
+ return time.Now().UTC().AddDate(0, 0, n).Format("2006-01-02")
+}
+
+func testAt(n int, hhmm string) string { return testDay(n) + "T" + hhmm }
+
// Editing one occurrence of a series is where calendars go wrong most
// visibly: the moved occurrence appears at its new time AND the
// original slot still shows the unmoved one, or the moved one vanishes
@@ -20,22 +41,22 @@ func TestMovingOneOccurrenceLeavesTheRestAlone(t *testing.T) {
loc := createEvent(t, h, session, url.Values{
"title": {"Daily standup"},
- "start": {"2026-09-02T09:30"},
- "end": {"2026-09-02T09:45"},
+ "start": {testAt(1, "09:30")},
+ "end": {testAt(1, "09:45")},
"kind": {"meeting"},
"status": {"confirmed"},
"repeat": {"daily"},
})
id := strings.TrimPrefix(loc, "/events/")
- // Move ONLY the 3rd, from 09:30 to 14:00.
+ // Move ONLY the second occurrence, from 09:30 to 14:00.
rec := postAs(t, h, session, "/events/"+id, url.Values{
"scope": {"this"},
- "occurrence": {"2026-09-03T09:30"},
+ "occurrence": {testAt(2, "09:30")},
"title": {"Daily standup"},
"calendar_id": {calendarIDOf(t, h, session)},
- "start": {"2026-09-03T14:00"},
- "end": {"2026-09-03T14:15"},
+ "start": {testAt(2, "14:00")},
+ "end": {testAt(2, "14:15")},
"kind": {"meeting"},
"status": {"confirmed"},
"repeat": {"none"},
@@ -50,7 +71,7 @@ func TestMovingOneOccurrenceLeavesTheRestAlone(t *testing.T) {
// day carries 48 slot links whose accessible names contain every
// half hour, so a bare Contains("09:30") matches on every day
// whether or not anything is scheduled then.
- moved := getAs(t, h, session, "/day/2026-09-03").Body.String()
+ moved := getAs(t, h, session, "/day/"+testDay(2)).Body.String()
if !hasChipAt(moved, "14:00") {
t.Errorf("the moved occurrence is not at its new time:\n%s", moved)
}
@@ -63,7 +84,7 @@ func TestMovingOneOccurrenceLeavesTheRestAlone(t *testing.T) {
}
// Every other day is untouched.
- for _, day := range []string{"2026-09-02", "2026-09-04"} {
+ for _, day := range []string{testDay(1), testDay(3)} {
body := getAs(t, h, session, "/day/"+day).Body.String()
if !hasChipAt(body, "09:30") {
t.Errorf("%s lost its 09:30 occurrence when a different day was moved", day)
@@ -89,8 +110,8 @@ func TestDeletingOneOccurrenceRemovesOnlyThatDay(t *testing.T) {
loc := createEvent(t, h, session, url.Values{
"title": {"Daily standup"},
- "start": {"2026-09-02T09:30"},
- "end": {"2026-09-02T09:45"},
+ "start": {testAt(1, "09:30")},
+ "end": {testAt(1, "09:45")},
"kind": {"meeting"},
"status": {"confirmed"},
"repeat": {"daily"},
@@ -99,16 +120,16 @@ func TestDeletingOneOccurrenceRemovesOnlyThatDay(t *testing.T) {
rec := postAs(t, h, session, "/events/"+id+"/delete", url.Values{
"scope": {"this"},
- "occurrence": {"2026-09-03T09:30"},
+ "occurrence": {testAt(2, "09:30")},
})
if rec.Code != http.StatusSeeOther {
t.Fatalf("deleting one occurrence: status %d", rec.Code)
}
- if body := getAs(t, h, session, "/day/2026-09-03").Body.String(); strings.Contains(body, "Daily standup") {
+ if body := getAs(t, h, session, "/day/"+testDay(2)).Body.String(); strings.Contains(body, "Daily standup") {
t.Error("the deleted occurrence is still on its day")
}
- for _, day := range []string{"2026-09-02", "2026-09-04"} {
+ for _, day := range []string{testDay(1), testDay(3)} {
if body := getAs(t, h, session, "/day/"+day).Body.String(); !strings.Contains(body, "Daily standup") {
t.Errorf("%s lost its occurrence when a different day was deleted", day)
}
@@ -123,8 +144,8 @@ func TestSplittingASeriesLeavesTheHeadAlone(t *testing.T) {
loc := createEvent(t, h, session, url.Values{
"title": {"Standup"},
- "start": {"2026-09-02T09:30"},
- "end": {"2026-09-02T09:45"},
+ "start": {testAt(1, "09:30")},
+ "end": {testAt(1, "09:45")},
"kind": {"meeting"},
"status": {"confirmed"},
"repeat": {"daily"},
@@ -133,11 +154,11 @@ func TestSplittingASeriesLeavesTheHeadAlone(t *testing.T) {
rec := postAs(t, h, session, "/events/"+id, url.Values{
"scope": {"following"},
- "occurrence": {"2026-09-10T09:30"},
+ "occurrence": {testAt(9, "09:30")},
"title": {"Standup"},
"calendar_id": {calendarIDOf(t, h, session)},
- "start": {"2026-09-10T11:00"},
- "end": {"2026-09-10T11:15"},
+ "start": {testAt(9, "11:00")},
+ "end": {testAt(9, "11:15")},
"kind": {"meeting"},
"status": {"confirmed"},
"repeat": {"daily"},
@@ -147,13 +168,13 @@ func TestSplittingASeriesLeavesTheHeadAlone(t *testing.T) {
}
// Before the split: still 09:30.
- before := getAs(t, h, session, "/day/2026-09-05").Body.String()
- if !strings.Contains(before, "09:30") {
+ before := getAs(t, h, session, "/day/"+testDay(4)).Body.String()
+ if !hasChipAt(before, "09:30") {
t.Errorf("an occurrence before the split lost its original time:\n%s", before)
}
// After: 11:00, and only once.
- after := getAs(t, h, session, "/day/2026-09-11").Body.String()
- if !strings.Contains(after, "11:00") {
+ after := getAs(t, h, session, "/day/"+testDay(10)).Body.String()
+ if !hasChipAt(after, "11:00") {
t.Errorf("an occurrence after the split is not at the new time:\n%s", after)
}
if n := strings.Count(after, "Standup"); n != 1 {