From d92dc56638b5660b930421c65d94ddf9edb80484 Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 14:36:22 -0400 Subject: [PATCH 01/17] Start a watch at its own start, not at HEY's cursor MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit hey watch --exit-on-first --timeout 20s exited at once on every run, printing a posting from eight days before; a plain watch reported that backlog on startup as if it had just happened. The first read of each box started from the since in its posting_changes_url, on the understanding that HEY bakes its clock in. It does not. HEY builds that since from Box#last_posting_activity_at — the latest updated_at among the box's unbundled postings, or the box's own updated_at when it has none — while the feed also answers deletions and bundled postings, so an empty Reply Later answers a deletion from last month on every start. And /boxes.json reaches the watch through the SDK's ETag cache: HEY's ETag for it is the box rows, which posting activity never touches, so a 304 serves the since as it stood when the list was first cached. Against the real account the cached Imbox since lagged the live one by twenty minutes, and the watch reported the posting in between. noLaterThan, which moved a later since back to the start, never fired against HEY either: its cursors carry microseconds, which the millisecond layout refused to parse. Every box now starts at the watch's start, keeping only the version from HEY's URL. The catch-up reports what happened after the start and nothing before, so --exit-on-first waits for a change; mail that lands between reading HEY's clock and reading the box list is still read, and is new. --since still reads back first, and a skip-ahead still resumes from HEY's since. The calendars' recording feeds and the calendar list start the same way: the list's since is the latest calendar updated_at, so a calendar deleted after the rest last changed was reported by the first poll of every watch. --- AGENTS.md | 15 +- docs/cli.md | 6 +- docs/omarchy.md | 12 +- internal/cmd/watch.go | 44 +++--- internal/cmd/watch_calendar.go | 36 ++--- internal/cmd/watch_calendar_test.go | 83 +++++++++-- internal/cmd/watch_new_test.go | 8 +- internal/cmd/watch_test.go | 205 ++++++++++++++++++++++++++-- skills/hey/SKILL.md | 3 +- 9 files changed, 329 insertions(+), 83 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 4fa85c55..d5d8726b 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -679,9 +679,14 @@ says (`--box` picks the boxes whose changes are reported; every box is followed) posting recorded as soon as it is classified. The start is the Date header translated back to when the request was made (mail that lands while the server answers is later than the start), it is taken before the box list, and each -box's cursor starts no later than it (`noLaterThan`): the server bakes the box's last posting -activity into the cursor, so mail that landed in between would otherwise sit behind the -cursor, read by nothing. That +box's cursor starts at it (`startingAt`), keeping only the version from the box's +`posting_changes_url`. The since HEY puts there is not its clock but the box's last posting +activity (`Box#last_posting_activity_at`: unbundled postings only, the box's own `updated_at` +when it has none), and the feed answers deletions and bundled postings later than that; and +`/boxes.json` comes through the SDK's ETag cache with an ETag of the box rows alone, which +posting activity does not touch, so a 304 serves the since as it was when the list was +cached. A read from HEY's since reported history as news on every start, and a since later +than the start would leave mail that landed in between behind it, read by nothing. That is HEY's semantics and state across events, so the CLI decides it once; what to do about it is the reader's. A 409 skip-ahead sets that box's floor at the cursor it skipped to (`newMail.skippedTo`): activity at or before it is never new there, known thread or not, @@ -785,8 +790,8 @@ watch that is down costs staleness, not a notice. `hey watch` follows the same streams on its own connection and reports the changes themselves (`internal/cmd/watch_calendar.go`). Rings are coalesced per calendar for `calendarCoalesceDelay`, then the calendar's recording feed is read from its cursor -(`Calendars().AllRecordingChanges`, cursors capped at the watch's start like the boxes' — -`calendarCursorNoLaterThan`) and each recording is a `recording_added`, `recording_updated` +(`Calendars().AllRecordingChanges`, cursors starting at the watch's start like the boxes' — +`calendarCursor`) and each recording is a `recording_added`, `recording_updated` or `recording_deleted` line naming its calendar where a mail line names its box. The poll reports `calendar_added`, `calendar_updated` and `calendar_deleted`, and a recording feed's 409 is `calendar_resync` after skipping ahead to a fresh cursor from the list. The diff --git a/docs/cli.md b/docs/cli.md index 3cdb14eb..80249ce6 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -336,7 +336,9 @@ hey watch --box imbox --events new --run-async 'notify-send -a HEY "New mail in hey watch --run-sync ./triage.sh # one at a time, waiting for each ``` -Runs until interrupted, printing changes as they happen, one line each: +Runs until interrupted, printing changes as they happen, one line each. What changed before +the watch began is not reported unless `--since` reads back to it first, so +`--exit-on-first` waits for a change rather than stopping on an old one: ```json {"change":"added","at":"2026-08-18T09:14:22.031Z","box":{"id":24088,"kind":"imbox","name":"Imbox"},"posting_id":98765,"thread_id":54321,"new":true,"posting":{}} @@ -344,7 +346,7 @@ Runs until interrupted, printing changes as they happen, one line each: Every `added` and `updated` line says whether the posting is new mail: unseen, not muted, and active since the watch last saw the thread — or since the watch began, for a thread it -has not seen, so a box's backlog is never new. Reading, muting or moving a thread is not new +has not seen, so the backlog `--since` reads is never new. Reading, muting or moving a thread is not new activity; a reply on a known thread is. `--events new` selects the new ones, alone or in a union with `added`, `updated`, `deleted` and `resync` — the default is everything but `new`, and `new` alone leaves a `resync` out, so a script for new mail never runs on one. `--box` diff --git a/docs/omarchy.md b/docs/omarchy.md index ae892f48..ef347be2 100644 --- a/docs/omarchy.md +++ b/docs/omarchy.md @@ -193,13 +193,15 @@ and `--events new` selects the true ones. The rule: translated back to the moment the request was made), the clock every `active_at` is on, so a workstation running fast or slow neither calls the backlog new nor sits on new mail; whole seconds, rounded down, so the doubt falls on the side of calling mail a moment old - new, and every box's cursor starts no later than that start, so mail that lands while the + new, and every box's cursor starts at that start, so mail that lands while the watch is starting up is read and is new. `active_at` moves on new mail only, not on a seen flip, a mute or a move, so reading a thread, marking it unseen again or moving it - into a box is never new, and a reply on a known thread is. A box's first read is its - catch-up from the server's cursor — the box's last activity, not this moment — so it - carries backlog, which the start-time rule keeps out, alongside anything that arrived - while the watch was starting, which is new. + into a box is never new, and a reply on a known thread is. A box's first read starts at + the watch's start, not at the server's cursor — the box's last posting activity, which a + deletion or a bundled posting can postdate, and which a cached box list can serve days + old — so it carries only what arrived while the + watch was starting, which is new. `--since` reads backlog first, which the start-time + rule keeps out. - **Every posting the watch reads is recorded**, in every box and whatever `--events` or `--box` reports — `--box` picks what is reported, every box is followed — so a thread known from a filtered-out change, or from another box, is never mistaken for new when its diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index a2a91935..dd9bb103 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -73,7 +73,8 @@ func newWatchCommand() *watchCommand { Use: "watch", Short: "Follow email threads and calendars as they change", Long: `Print email threads and calendar changes as they happen: piped or with --json, one -JSON object per line; at a terminal, one text line each. Runs until interrupted. +JSON object per line; at a terminal, one text line each. Runs until interrupted. What +changed before the watch began is not reported, unless --since reads back to it first. Changes can drive a command instead of being printed, and that is a choice between two behaviours: --run-async spawns the command per change and moves on, so a slow one never @@ -82,7 +83,7 @@ Pass one or the other. Every added and updated line says whether the thread is new mail: unseen, not muted, and active since the watch last saw it — or since the watch began, for a thread it has not -seen, so the backlog a box's first read carries is not new. Reading a thread, muting or +seen, so the backlog --since reads is not new. Reading a thread, muting or moving it is not new activity; a reply on a known thread is. --events new selects the new ones, alone or alongside added, updated and deleted, and a script sees HEY_NEW=1 for them. @@ -150,8 +151,8 @@ func (c *watchCommand) run(cmd *cobra.Command, args []string) error { } // New mail is measured against the watch's start, so that is taken before - // the boxes' cursors are read — and the cursors start no later than it, so - // nothing that lands between the two sits behind a cursor, read by nothing. + // the boxes' cursors are read — and the cursors start at it, so nothing + // that lands between the two sits behind a cursor, read by nothing. started := serverNow(ctx) newMail := trackNewMail(started) @@ -276,7 +277,7 @@ func (c *watchCommand) watchedBoxes(ctx context.Context, started time.Time) (map continue } if c.since == "" { - cursor = noLaterThan(cursor, started) + cursor = startingAt(cursor, started) } watched[box.Id] = &watchedBox{id: box.Id, kind: box.Kind, name: box.Name, cursor: cursor, reported: c.watching(box)} @@ -306,8 +307,9 @@ func boxIs(box generated.Box, wanted string) bool { wanted == strconv.FormatInt(box.Id, 10) } -// watchCursor is where a box's changes feed should be read from. The server bakes its own -// clock into the box's changes URL, so that's the cursor unless --since moves it. +// watchCursor reads the cursor out of a box's changes URL — HEY's own, which a skip-ahead +// resumes from — unless --since moves it. A watch's first read starts at the watch's +// start instead (startingAt). func watchCursor(changesURL, since string) (hey.PostingChangesCursor, error) { if changesURL == "" { return hey.PostingChangesCursor{}, nil @@ -332,19 +334,21 @@ func watchCursor(changesURL, since string) (hey.PostingChangesCursor, error) { const watchCursorTimeLayout = "2006-01-02T15:04:05.000Z" -// noLaterThan moves a box's cursor back to the watch's start when the box's -// own is later. The server bakes the box's last posting activity into its -// cursor, so mail that landed after the watch read HEY's clock and before it -// read the box list is already behind the cursor: the feed would start after -// it, and nothing would ever report it. Starting from the watch's own start -// reads it as part of the catch-up instead — and it is new, since it is later -// than the start. A cursor that cannot be read is left as it is. -func noLaterThan(cursor hey.PostingChangesCursor, started time.Time) hey.PostingChangesCursor { - at, err := time.Parse(watchCursorTimeLayout, cursor.Since) - if err == nil && at.After(started) { - cursor.Since = started.UTC().Format(watchCursorTimeLayout) - } - +// startingAt starts a feed's cursor at the watch's start, keeping the version HEY's +// URL names. The since HEY serves is not its clock but the box's last posting +// activity — the latest updated_at among its unbundled postings, or the box's own +// when it has none — and the feed answers changes later than that which are history +// by now: a deletion, a bundled posting. Nor is it always even that: the box list +// comes through the SDK's ETag cache, HEY's ETag for it is the box rows, and posting +// activity does not touch them, so a 304 hands back the since as it stood when the +// list was cached — hours or days behind. Read from there, the catch-up reported +// what came after as news on every start, and --exit-on-first stopped on the first +// of it. From the start it +// reports what happened after it and nothing before — including mail that landed +// after the watch read HEY's clock and before it read the box list, which a cursor +// later than the start would leave behind it, read by nothing. That mail is new, too. +func startingAt(cursor hey.PostingChangesCursor, started time.Time) hey.PostingChangesCursor { + cursor.Since = started.UTC().Format(watchCursorTimeLayout) return cursor } diff --git a/internal/cmd/watch_calendar.go b/internal/cmd/watch_calendar.go index 35b26fd5..72955ea1 100644 --- a/internal/cmd/watch_calendar.go +++ b/internal/cmd/watch_calendar.go @@ -79,9 +79,11 @@ func (c *watchCommand) watchingCalendars(changes map[string]bool) bool { } // watchedCalendars reads the calendars and where each one's feed should be read from. The -// cursors are capped at the watch's start the way the boxes' are — the server bakes each -// calendar's last activity into its URL, so a write that lands between reading the clock -// and reading the list would otherwise sit behind the cursor, read by nothing. +// cursors start at the watch's start the way the boxes' do: the since HEY serves is a +// calendar's own updated_at — for the list, the latest of them — not HEY's clock, and a +// calendar deleted after the rest last changed is later than that, so a first poll from +// it would report the deletion as news on every start; and a write that lands between +// reading the clock and reading the list would sit behind a later one, read by nothing. func (c *watchCommand) watchedCalendars(ctx context.Context, started time.Time) (*calendarsWatch, error) { list, err := sdk.Calendars().ListWithChanges(ctx) if err != nil { @@ -129,37 +131,25 @@ func (c *watchCommand) followedCalendar(listed hey.ListedCalendar, started time. }, nil } -// calendarCursor is where a feed should be read from: the URL HEY served, moved by -// --since, and otherwise capped at the watch's start. +// calendarCursor is where a feed should be read from: the feed and version the URL HEY +// served names, from --since or else from the watch's start. func (c *watchCommand) calendarCursor(changesURL string, started time.Time) (hey.CalendarChangesCursor, error) { cursor, err := hey.CalendarChangesCursorFrom(changesURL) if err != nil { return hey.CalendarChangesCursor{}, apierr.FromSDK(err) } - if c.since == "" { - return calendarCursorNoLaterThan(cursor, started), nil - } - at, err := parseWatchSince(c.since) - if err != nil { - return hey.CalendarChangesCursor{}, err + from := started + if c.since != "" { + if from, err = parseWatchSince(c.since); err != nil { + return hey.CalendarChangesCursor{}, err + } } - cursor.Since = at.UTC().Format(watchCursorTimeLayout) + cursor.Since = from.UTC().Format(watchCursorTimeLayout) return cursor, nil } -// calendarCursorNoLaterThan is noLaterThan for a calendar feed's cursor, and exists for -// the same race. A cursor that cannot be read is left as it is. -func calendarCursorNoLaterThan(cursor hey.CalendarChangesCursor, started time.Time) hey.CalendarChangesCursor { - at, err := time.Parse(watchCursorTimeLayout, cursor.Since) - if err == nil && at.After(started) { - cursor.Since = started.UTC().Format(watchCursorTimeLayout) - } - - return cursor -} - // calendarDisplayName is what a calendar is called on a watch line. The personal calendar // has no name of its own — HEY leaves the field empty and the web app labels it from the // identity — so the watch says what it is rather than nothing. diff --git a/internal/cmd/watch_calendar_test.go b/internal/cmd/watch_calendar_test.go index e1fc710e..a246af07 100644 --- a/internal/cmd/watch_calendar_test.go +++ b/internal/cmd/watch_calendar_test.go @@ -6,6 +6,7 @@ import ( "net/http" "net/http/httptest" "strings" + "sync" "testing" "time" @@ -59,8 +60,17 @@ func TestCalendarCursor(t *testing.T) { if err != nil { t.Fatalf("unexpected error: %v", err) } - if cursor.Since != "2026-08-18T09:00:00.000Z" || cursor.Version != "1" { - t.Errorf("cursor = %+v, want the server's own since and version", cursor) + if cursor.Since != "2026-08-18T10:00:00.000Z" || cursor.Version != "1" { + t.Errorf("cursor = %+v, want the watch's start and the server's version", cursor) + } + + later := "https://app.hey.com/calendars/512/recording/changes.json?since=2026-08-18T10%3A30%3A00.518496Z&v=1" + cursor, err = command.calendarCursor(later, started) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if cursor.Since != "2026-08-18T10:00:00.000Z" { + t.Errorf("since = %q, want a cursor later than the start moved back to it", cursor.Since) } command.since = "2026-08-17T08:30:00Z" @@ -81,22 +91,69 @@ func TestCalendarCursor(t *testing.T) { } } -func TestCalendarCursorNoLaterThan(t *testing.T) { - started := time.Date(2026, 8, 18, 9, 0, 0, 0, time.UTC) +// The list's cursor is the latest updated_at of the calendars still on it, so a calendar +// deleted after the rest last changed is later than it — and history by the time the +// watch starts. The feed here answers what is strictly later than its cursor, as HEY's +// does. +func TestWatchPollDoesNotReportHistoryAsItStarts(t *testing.T) { + t.Setenv("HEY_TOKEN", "test-token") - late := hey.CalendarChangesCursor{Since: "2026-08-18T09:30:00.000Z", Version: "1"} - if capped := calendarCursorNoLaterThan(late, started); capped.Since != "2026-08-18T09:00:00.000Z" { - t.Errorf("since = %q, want a cursor later than the start moved back to it", capped.Since) + var mu sync.Mutex + deletedAt := "2026-08-20T16:42:07.204613Z" + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + mu.Lock() + defer mu.Unlock() + w.Header().Set("Content-Type", "application/json") + switch r.URL.Path { + case "/calendars.json": + _, _ = w.Write([]byte(`{ + "calendars": [{"calendar": {"id": 512, "name": "Household"}, + "recording_changes_url": "/calendars/512/recording/changes.json?since=2026-08-18T11%3A00%3A00.000000Z&v=1", + "signed_stream_name": "signed-household"}], + "calendar_changes_url": "/calendar/changes.json?since=2026-08-18T11%3A00%3A00.000000Z" + }`)) + case "/calendar/changes.json": + since, err := time.Parse(time.RFC3339Nano, r.URL.Query().Get("since")) + deleted, _ := time.Parse(time.RFC3339Nano, deletedAt) + if err != nil || !deleted.After(since) { + _, _ = w.Write([]byte(`{}`)) + return + } + w.Header().Set("Link", `; rel="next"`) + _, _ = w.Write([]byte(`{"deleted": [{"id": 513, "deleted_at": "` + deletedAt + `"}]}`)) + default: + http.NotFound(w, r) + } + })) + defer server.Close() + initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) + + calendars, err := newWatchCommand().watchedCalendars(context.Background(), watchStarted) + if err != nil { + t.Fatalf("unexpected error: %v", err) } + t.Cleanup(calendars.poll.Stop) + watch, out := newTestWatch(defaultChanges...) + watch.exitOnFirst = true + watch.calendar = calendars - early := hey.CalendarChangesCursor{Since: "2026-08-18T08:00:00.000Z"} - if kept := calendarCursorNoLaterThan(early, started); kept.Since != "2026-08-18T08:00:00.000Z" { - t.Errorf("since = %q, want a cursor before the start left alone", kept.Since) + if err := watch.pollCalendarList(context.Background()); err != nil { + t.Fatalf("unexpected error: %v", err) + } + if out.Len() != 0 || watch.finished() { + t.Fatalf("wrote %q, want nothing for a calendar deleted before the watch began", out.String()) } - unreadable := hey.CalendarChangesCursor{Since: "whenever"} - if kept := calendarCursorNoLaterThan(unreadable, started); kept.Since != "whenever" { - t.Errorf("since = %q, want a cursor we can't read left as it is", kept.Since) + // A calendar deleted after the watch began is a change. + mu.Lock() + deletedAt = "2026-08-21T09:04:31.880112Z" + mu.Unlock() + if err := watch.pollCalendarList(context.Background()); err != nil { + t.Fatalf("unexpected error: %v", err) + } + lines := watchLines(t, out) + if len(lines) != 1 || lines[0]["change"] != watchCalendarDeleted || !watch.finished() { + t.Errorf("wrote %v, want the deletion after the start, ending the watch", lines) } } diff --git a/internal/cmd/watch_new_test.go b/internal/cmd/watch_new_test.go index 120afa57..6d5d8a96 100644 --- a/internal/cmd/watch_new_test.go +++ b/internal/cmd/watch_new_test.go @@ -249,16 +249,16 @@ func TestCutoffBeforeIsAWholeMillisecondStrictlyBefore(t *testing.T) { t.Errorf("cutoffBefore(%v) = %v, want strictly before even on a boundary", exact, got) } - // So mail in the start's own millisecond is new, and a cursor at that - // millisecond is moved back to before it. + // So mail in the start's own millisecond is new, and a cursor started at + // the watch's start reads it: the feed answers what is strictly later. tracker := trackNewMail(cutoffBefore(within)) landed := within.Truncate(time.Millisecond) if !tracker.isNew(24088, newPosting(101, "Maria Delgado", "Lunch on Thursday?", landed)) { t.Error("mail in the same millisecond as the watch's start is new") } - cursor := noLaterThan(hey.PostingChangesCursor{Since: landed.Format(watchCursorTimeLayout)}, cutoffBefore(within)) + cursor := startingAt(hey.PostingChangesCursor{Since: landed.Format(watchCursorTimeLayout)}, cutoffBefore(within)) if cursor.Since != "2026-08-21T09:00:05.122Z" { - t.Errorf("cursor = %q, want it moved back to before the millisecond the mail landed in", cursor.Since) + t.Errorf("cursor = %q, want it before the millisecond the mail landed in", cursor.Since) } } diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index 969a37ae..17098885 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -12,6 +12,7 @@ import ( "os" "slices" "strings" + "sync" "testing" "time" @@ -851,14 +852,15 @@ func TestWatchDoesNotSayReadyOnItsWayOut(t *testing.T) { } } -func TestWatchedBoxesStartNoLaterThanTheWatchDid(t *testing.T) { +func TestWatchedBoxesStartAtTheWatchsStart(t *testing.T) { t.Setenv("HEY_TOKEN", "test-token") server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-Type", "application/json") // The Imbox's last activity is after the watch read HEY's clock — mail - // landed in between; The Feed's is before. - _, _ = w.Write([]byte(`[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"/boxes/24088/postings/changes.json?since=2026-08-21T09%3A00%3A30.000Z&v=2"},` + - `{"id":24089,"kind":"feedbox","name":"The Feed","posting_changes_url":"/boxes/24089/postings/changes.json?since=2026-08-21T08%3A00%3A00.000Z&v=2"}]`)) + // landed in between; The Feed's is before, and its feed may still hold + // changes later than that which are history all the same. + _, _ = w.Write([]byte(`[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"/boxes/24088/postings/changes.json?since=2026-08-21T09%3A00%3A30.183221Z&v=2"},` + + `{"id":24089,"kind":"feedbox","name":"The Feed","posting_changes_url":"/boxes/24089/postings/changes.json?since=2026-08-21T08%3A00%3A00.518496Z&v=2"}]`)) })) defer server.Close() initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) @@ -868,11 +870,10 @@ func TestWatchedBoxesStartNoLaterThanTheWatchDid(t *testing.T) { if err != nil { t.Fatalf("unexpected error: %v", err) } - if got := boxes[24088].cursor.Since; got != "2026-08-21T09:00:00.000Z" { - t.Errorf("Imbox cursor = %q, want it moved back to the watch's start so the mail in between is read", got) - } - if got := boxes[24089].cursor.Since; got != "2026-08-21T08:00:00.000Z" { - t.Errorf("Feed cursor = %q, want the box's own when it is earlier", got) + for _, id := range []int64{24088, 24089} { + if got := boxes[id].cursor; got.Since != "2026-08-21T09:00:00.000Z" || got.Version != "2" { + t.Errorf("%s cursor = %+v, want the watch's start and HEY's version, whatever since HEY served", boxes[id].name, got) + } } if !boxes[24088].reported || !boxes[24089].reported { t.Error("without --box every box is reported") @@ -894,7 +895,7 @@ func TestWatchedBoxesStartNoLaterThanTheWatchDid(t *testing.T) { } command.boxes = nil - // --since is the reader's choice and wins over both. + // --since is the reader's choice and wins over the start. command.since = "2026-08-21T09:30:00Z" boxes, err = command.watchedBoxes(context.Background(), watchStarted) if err != nil { @@ -905,6 +906,190 @@ func TestWatchedBoxesStartNoLaterThanTheWatchDid(t *testing.T) { } } +// heyHistory is HEY as a watch's startup meets it: its clock, the box list, and a +// changes feed that answers what is strictly later than its cursor, the way HEY's does. +// Each box's posting_changes_url carries what HEY puts there — the box's last posting +// activity, the latest updated_at among its unbundled postings, or the box's own +// updated_at when it has none — not the time, and a cached box list serves it as it +// was when cached. So the feed can answer a change later than that cursor that is +// history all the same. +type heyHistory struct { + mu sync.Mutex + cursors map[int64]string + changes map[int64][]historyChange +} + +type historyChange struct { + at string + deleted bool + id int64 + subject string +} + +// The clock the server answers with; a watch's start is taken a moment before it. +const heyHistoryDate = "Fri, 21 Aug 2026 09:00:05 GMT" + +func newHEYHistory(t *testing.T) *heyHistory { + t.Helper() + history := &heyHistory{ + cursors: map[int64]string{ + // The Imbox's since as a box list cached before its latest posting serves it. + 24088: "2026-08-20T23:45:00.000000Z", + // Reply Later is empty, so its cursor is the box's own updated_at — years + // before the posting deleted from it last week. + 24091: "2020-06-16T11:22:18.853469Z", + }, + changes: map[int64][]historyChange{ + 24088: {{at: "2026-08-20T23:45:39.083350Z", id: 9001, subject: "Lunch on Thursday?"}}, + 24091: {{at: "2026-08-19T01:07:15.496840Z", id: 9002, deleted: true}}, + }, + } + + server := httptest.NewServer(http.HandlerFunc(history.serve)) + t.Cleanup(server.Close) + t.Setenv("HEY_TOKEN", "test-token") + initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) + + return history +} + +// land is a change arriving at HEY, whose box's cursor is now its last activity. +func (h *heyHistory) land(boxID int64, change historyChange) { + h.mu.Lock() + defer h.mu.Unlock() + h.changes[boxID] = append(h.changes[boxID], change) + h.cursors[boxID] = change.at +} + +func (h *heyHistory) serve(w http.ResponseWriter, r *http.Request) { + h.mu.Lock() + defer h.mu.Unlock() + + w.Header().Set("Content-Type", "application/json") + var boxID int64 + switch { + case r.URL.Path == "/identity.json": + w.Header().Set("Date", heyHistoryDate) + _, _ = w.Write([]byte(`{"id":1}`)) + case r.URL.Path == "/boxes.json": + _, _ = fmt.Fprintf(w, `[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"/boxes/24088/postings/changes.json?since=%s&v=2"},`+ + `{"id":24091,"kind":"laterbox","name":"Reply Later","posting_changes_url":"/boxes/24091/postings/changes.json?since=%s&v=2"}]`, + h.cursors[24088], h.cursors[24091]) + case scanBox(r.URL.Path, &boxID): + h.serveChanges(w, boxID, r.URL.Query().Get("since")) + default: + http.NotFound(w, r) + } +} + +func scanBox(path string, boxID *int64) bool { + _, err := fmt.Sscanf(path, "/boxes/%d/postings/changes.json", boxID) + return err == nil +} + +func (h *heyHistory) serveChanges(w http.ResponseWriter, boxID int64, since string) { + from, err := time.Parse(time.RFC3339Nano, since) + if err != nil { + w.WriteHeader(http.StatusBadRequest) + return + } + + var added, deleted []string + var last string + for _, change := range h.changes[boxID] { + at, _ := time.Parse(time.RFC3339Nano, change.at) + if !at.After(from) { + continue + } + last = change.at + if change.deleted { + deleted = append(deleted, fmt.Sprintf(`{"id":%d,"deleted_at":%q}`, change.id, change.at)) + } else { + added = append(added, fmt.Sprintf(`{"id":%d,"kind":"topic","box_id":%d,"name":%q,"created_at":%q,"updated_at":%q,"active_at":%q,"creator":{"name":"Maria Delgado"}}`, + change.id, boxID, change.subject, change.at, change.at, change.at)) + } + } + if last != "" { + w.Header().Set("Link", fmt.Sprintf(`; rel="next"`, boxID, last)) + } + _, _ = fmt.Fprintf(w, `{"added":[%s],"deleted":[%s]}`, strings.Join(added, ","), strings.Join(deleted, ",")) +} + +// startWatch begins a watch the way run does: HEY's clock, then the boxes, then the +// catch-up. +func startWatch(t *testing.T, command *watchCommand, watch *postingsWatch) { + t.Helper() + started := serverNow(context.Background()) + boxes, err := command.watchedBoxes(context.Background(), started) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + watch.boxes = boxes + watch.newMail = trackNewMail(started) + if err := watch.catchUp(context.Background()); err != nil { + t.Fatalf("unexpected error: %v", err) + } +} + +func TestWatchDoesNotReportHistoryAsItStarts(t *testing.T) { + history := newHEYHistory(t) + watch, out := newTestWatch(defaultChanges...) + watch.exitOnFirst = true + + startWatch(t, newWatchCommand(), watch) + + lines := watchLines(t, out) + if len(lines) != 1 || lines[0]["change"] != "ready" { + t.Fatalf("wrote %v, want ready alone — a deletion and a posting from before the watch began are history", lines) + } + if watch.finished() { + t.Fatal("--exit-on-first should still be waiting for a change") + } + + // A reply lands after the watch began: that is the change it was waiting for. + history.land(24088, historyChange{at: "2026-08-21T09:00:12.250000Z", id: 9003, subject: "Re: Lunch on Thursday?"}) + ringBox(t, watch) + + lines = watchLines(t, out) + if len(lines) != 2 || lines[1]["change"] != "added" || lines[1]["posting_id"] != float64(9003) || lines[1]["new"] != true { + t.Errorf("wrote %v, want the reply that landed after the start, new", lines) + } + if !watch.finished() { + t.Error("--exit-on-first should end on the change that landed after the start") + } +} + +func TestWatchReadsMailThatLandedBeforeItReadTheBoxes(t *testing.T) { + history := newHEYHistory(t) + // The watch reads HEY's clock a moment before the Date header; this lands on the + // header's second, after the start and before the box list, so the Imbox's cursor is + // already past it. + history.land(24088, historyChange{at: "2026-08-21T09:00:05.000000Z", id: 9003, subject: "Invoice #4021"}) + watch, out := newTestWatch(defaultChanges...) + + startWatch(t, newWatchCommand(), watch) + + lines := watchLines(t, out) + if len(lines) != 2 || lines[0]["posting_id"] != float64(9003) || lines[0]["new"] != true || lines[1]["change"] != "ready" { + t.Errorf("wrote %v, want the mail that landed during startup, new, then ready — and no history", lines) + } +} + +func TestWatchSinceReadsTheHistoryFirst(t *testing.T) { + newHEYHistory(t) + command := newWatchCommand() + command.since = "2026-08-19" + watch, out := newTestWatch(defaultChanges...) + + startWatch(t, command, watch) + + lines := watchLines(t, out) + if len(lines) != 3 || lines[0]["posting_id"] != float64(9001) || lines[0]["new"] != false || + lines[1]["change"] != "deleted" || lines[1]["posting_id"] != float64(9002) || lines[2]["change"] != "ready" { + t.Errorf("wrote %v, want both changes since --since, not new, then ready", lines) + } +} + func TestWatchAnnouncesADropBeforeTheReconnectThatFollowedIt(t *testing.T) { server := changesServer(t, `{}`) watch, _ := newTestWatch("added") diff --git a/skills/hey/SKILL.md b/skills/hey/SKILL.md index 4ed1d5ee..a752623d 100644 --- a/skills/hey/SKILL.md +++ b/skills/hey/SKILL.md @@ -714,8 +714,9 @@ stdout, one per line, instead of the usual envelope (at a terminal, one text lin "name"}, "posting_id": ..., "thread_id": ..., "new": true|false, "posting": {...}}`. Use `thread_id` with `hey thread read` (absent for a bundle row that names no single thread). `new` is on every `added` and `updated` line and says whether the posting is new mail — unseen, not muted, and active since the watch last saw the thread, -or since the watch began for a thread it has not seen; the backlog a watch starts with is +or since the watch began for a thread it has not seen; the backlog `--since` reads is never new, nor is reading, muting or moving a thread, and a reply on a known thread is. +Without `--since`, nothing from before the watch began is reported at all. `--events new` selects the new ones, alone or in a union with the other three. A deleted posting carries no `posting`, `thread_id` or `new`. Three more lines describe the watch itself: `{"change": "ready"}` once every box and calendar is caught up and the subscription From d34d3dc5750049844d3d633e5fbce2196003a865 Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 14:37:02 -0400 Subject: [PATCH 02/17] Set a skip-ahead's new-mail floor from HEY's own cursor MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A box that answers 409 is skipped ahead to the since in its posting_changes_url, and that since becomes the box's floor: activity at or before it is never new there, because the watch never read the gap. The floor was read in the watch's millisecond layout, and HEY writes the since to the microsecond, so the parse failed and no floor was ever set against the real server — a thread moved or labelled while unseen in the gap could read as new mail. The since is now read as RFC 3339 with any fraction. --- internal/cmd/watch_new.go | 6 ++++-- internal/cmd/watch_new_test.go | 6 ++++++ 2 files changed, 10 insertions(+), 2 deletions(-) diff --git a/internal/cmd/watch_new.go b/internal/cmd/watch_new.go index a29775a9..e3f6b798 100644 --- a/internal/cmd/watch_new.go +++ b/internal/cmd/watch_new.go @@ -45,9 +45,11 @@ func trackNewMail(started time.Time) *newMail { // the box's last posting activity, which bounds every thread in it. The floor // is the box's alone — a gap thread that moves to another box is measured // there, and may still read as new once. The resync line is the reader's cue -// to re-read the box either way. +// to re-read the box either way. HEY writes the cursor to the microsecond, so +// it is read as RFC 3339 with any fraction rather than in the watch's own +// millisecond layout, which refuses it. func (n *newMail) skippedTo(boxID int64, cursor hey.PostingChangesCursor) { - if at, err := time.Parse(watchCursorTimeLayout, cursor.Since); err == nil { + if at, err := time.Parse(time.RFC3339Nano, cursor.Since); err == nil { n.floors[boxID] = at } } diff --git a/internal/cmd/watch_new_test.go b/internal/cmd/watch_new_test.go index 6d5d8a96..d7b00c90 100644 --- a/internal/cmd/watch_new_test.go +++ b/internal/cmd/watch_new_test.go @@ -162,6 +162,12 @@ func TestNewMailAfterASkipAheadIsSinceTheSkip(t *testing.T) { if _, has := tracker.floors[24089]; has { t.Error("an unreadable cursor must not become a floor") } + + // HEY writes its cursors to the microsecond. + tracker.skippedTo(24090, hey.PostingChangesCursor{Since: "2026-08-21T10:00:00.518496Z", Version: "2"}) + if got := tracker.floors[24090]; !got.Equal(time.Date(2026, 8, 21, 10, 0, 0, 518496000, time.UTC)) { + t.Errorf("floor = %v, want the cursor HEY wrote, to the microsecond", got) + } } func TestNewMailCarriedTwiceByOneReadIsNewOnce(t *testing.T) { From b6332aeea10e3b5aa6cc5a7e6f986b2c43bd35a5 Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 14:46:36 -0400 Subject: [PATCH 03/17] Keep HEY's cursor when only the local clock says when a watch began serverNow falls back to the workstation's clock when HEY's cannot be read, and a start on that clock is only as good as the clock: a fast one puts it in HEY's future, where every change until then would go unread. The start now says which clock it came from. On HEY's, a feed starts at the start as before; on the workstation's alone, HEY's own since is kept when it is the earlier of the two, or cannot be read. That may report the history this branch set out to suppress, but only when HEY's clock could not be read, and missing mail is worse than repeating it. --- internal/cmd/watch.go | 28 +++------------ internal/cmd/watch_calendar.go | 29 ++++++++-------- internal/cmd/watch_calendar_test.go | 4 +-- internal/cmd/watch_new.go | 53 +++++++++++++++++++++++++---- internal/cmd/watch_new_test.go | 53 ++++++++++++++++++++++++----- internal/cmd/watch_test.go | 10 +++--- 6 files changed, 119 insertions(+), 58 deletions(-) diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index dd9bb103..d98e24d9 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -154,7 +154,7 @@ func (c *watchCommand) run(cmd *cobra.Command, args []string) error { // the boxes' cursors are read — and the cursors start at it, so nothing // that lands between the two sits behind a cursor, read by nothing. started := serverNow(ctx) - newMail := trackNewMail(started) + newMail := trackNewMail(started.at) boxes, err := c.watchedBoxes(ctx, started) if err != nil { @@ -253,7 +253,7 @@ func (c *watchCommand) watchedChanges() (map[string]bool, error) { return changes, nil } -func (c *watchCommand) watchedBoxes(ctx context.Context, started time.Time) (map[int64]*watchedBox, error) { +func (c *watchCommand) watchedBoxes(ctx context.Context, started watchStart) (map[int64]*watchedBox, error) { listed, err := sdk.Boxes().List(ctx) if err != nil { return nil, apierr.FromSDK(err) @@ -277,7 +277,7 @@ func (c *watchCommand) watchedBoxes(ctx context.Context, started time.Time) (map continue } if c.since == "" { - cursor = startingAt(cursor, started) + cursor.Since = started.since(cursor.Since) } watched[box.Id] = &watchedBox{id: box.Id, kind: box.Kind, name: box.Name, cursor: cursor, reported: c.watching(box)} @@ -308,8 +308,8 @@ func boxIs(box generated.Box, wanted string) bool { } // watchCursor reads the cursor out of a box's changes URL — HEY's own, which a skip-ahead -// resumes from — unless --since moves it. A watch's first read starts at the watch's -// start instead (startingAt). +// resumes from — unless --since moves it. Without --since, a watch's first read starts +// at the watch's start instead (watchStart.since). func watchCursor(changesURL, since string) (hey.PostingChangesCursor, error) { if changesURL == "" { return hey.PostingChangesCursor{}, nil @@ -334,24 +334,6 @@ func watchCursor(changesURL, since string) (hey.PostingChangesCursor, error) { const watchCursorTimeLayout = "2006-01-02T15:04:05.000Z" -// startingAt starts a feed's cursor at the watch's start, keeping the version HEY's -// URL names. The since HEY serves is not its clock but the box's last posting -// activity — the latest updated_at among its unbundled postings, or the box's own -// when it has none — and the feed answers changes later than that which are history -// by now: a deletion, a bundled posting. Nor is it always even that: the box list -// comes through the SDK's ETag cache, HEY's ETag for it is the box rows, and posting -// activity does not touch them, so a 304 hands back the since as it stood when the -// list was cached — hours or days behind. Read from there, the catch-up reported -// what came after as news on every start, and --exit-on-first stopped on the first -// of it. From the start it -// reports what happened after it and nothing before — including mail that landed -// after the watch read HEY's clock and before it read the box list, which a cursor -// later than the start would leave behind it, read by nothing. That mail is new, too. -func startingAt(cursor hey.PostingChangesCursor, started time.Time) hey.PostingChangesCursor { - cursor.Since = started.UTC().Format(watchCursorTimeLayout) - return cursor -} - func parseWatchSince(since string) (time.Time, error) { if at, err := time.Parse(time.RFC3339, since); err == nil { return at, nil diff --git a/internal/cmd/watch_calendar.go b/internal/cmd/watch_calendar.go index 72955ea1..40f0387f 100644 --- a/internal/cmd/watch_calendar.go +++ b/internal/cmd/watch_calendar.go @@ -79,12 +79,11 @@ func (c *watchCommand) watchingCalendars(changes map[string]bool) bool { } // watchedCalendars reads the calendars and where each one's feed should be read from. The -// cursors start at the watch's start the way the boxes' do: the since HEY serves is a -// calendar's own updated_at — for the list, the latest of them — not HEY's clock, and a -// calendar deleted after the rest last changed is later than that, so a first poll from -// it would report the deletion as news on every start; and a write that lands between -// reading the clock and reading the list would sit behind a later one, read by nothing. -func (c *watchCommand) watchedCalendars(ctx context.Context, started time.Time) (*calendarsWatch, error) { +// cursors start at the watch's start the way the boxes' do (watchStart.since): the since +// HEY serves is a calendar's own updated_at — for the list, the latest of them — so a +// calendar deleted after the rest last changed was reported by the first poll of every +// watch. +func (c *watchCommand) watchedCalendars(ctx context.Context, started watchStart) (*calendarsWatch, error) { list, err := sdk.Calendars().ListWithChanges(ctx) if err != nil { return nil, apierr.FromSDK(err) @@ -117,7 +116,7 @@ func (c *watchCommand) watchedCalendars(ctx context.Context, started time.Time) return watch, nil } -func (c *watchCommand) followedCalendar(listed hey.ListedCalendar, started time.Time) (*watchedCalendar, error) { +func (c *watchCommand) followedCalendar(listed hey.ListedCalendar, started watchStart) (*watchedCalendar, error) { cursor, err := c.calendarCursor(listed.RecordingChangesURL, started) if err != nil { return nil, err @@ -133,19 +132,21 @@ func (c *watchCommand) followedCalendar(listed hey.ListedCalendar, started time. // calendarCursor is where a feed should be read from: the feed and version the URL HEY // served names, from --since or else from the watch's start. -func (c *watchCommand) calendarCursor(changesURL string, started time.Time) (hey.CalendarChangesCursor, error) { +func (c *watchCommand) calendarCursor(changesURL string, started watchStart) (hey.CalendarChangesCursor, error) { cursor, err := hey.CalendarChangesCursorFrom(changesURL) if err != nil { return hey.CalendarChangesCursor{}, apierr.FromSDK(err) } + if c.since == "" { + cursor.Since = started.since(cursor.Since) + return cursor, nil + } - from := started - if c.since != "" { - if from, err = parseWatchSince(c.since); err != nil { - return hey.CalendarChangesCursor{}, err - } + at, err := parseWatchSince(c.since) + if err != nil { + return hey.CalendarChangesCursor{}, err } - cursor.Since = from.UTC().Format(watchCursorTimeLayout) + cursor.Since = at.UTC().Format(watchCursorTimeLayout) return cursor, nil } diff --git a/internal/cmd/watch_calendar_test.go b/internal/cmd/watch_calendar_test.go index a246af07..fd3cd34f 100644 --- a/internal/cmd/watch_calendar_test.go +++ b/internal/cmd/watch_calendar_test.go @@ -53,7 +53,7 @@ func TestWatchingCalendars(t *testing.T) { func TestCalendarCursor(t *testing.T) { changesURL := "https://app.hey.com/calendars/512/recording/changes.json?since=2026-08-18T09%3A00%3A00.000Z&v=1" - started := time.Date(2026, 8, 18, 10, 0, 0, 0, time.UTC) + started := watchStart{at: time.Date(2026, 8, 18, 10, 0, 0, 0, time.UTC), onServerClock: true} command := newWatchCommand() cursor, err := command.calendarCursor(changesURL, started) @@ -128,7 +128,7 @@ func TestWatchPollDoesNotReportHistoryAsItStarts(t *testing.T) { defer server.Close() initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) - calendars, err := newWatchCommand().watchedCalendars(context.Background(), watchStarted) + calendars, err := newWatchCommand().watchedCalendars(context.Background(), serverStart) if err != nil { t.Fatalf("unexpected error: %v", err) } diff --git a/internal/cmd/watch_new.go b/internal/cmd/watch_new.go index e3f6b798..e9c3e8da 100644 --- a/internal/cmd/watch_new.go +++ b/internal/cmd/watch_new.go @@ -69,19 +69,60 @@ func (n *newMail) skippedTo(boxID int64, cursor hey.PostingChangesCursor) { // calling mail a moment old new rather than mail a moment new old. The SDK // caches GETs by URL, so a query the server ignores keeps this one out of the // cache; and when the server's clock can't be read, the local clock at the -// start stands in. Either way the start is handed out as a cutoff: a whole -// millisecond, strictly before the instant it stands for. -func serverNow(ctx context.Context) time.Time { +// start stands in, and the start says so. Either way it is handed out as a +// cutoff: a whole millisecond, strictly before the instant it stands for. +func serverNow(ctx context.Context) watchStart { started := time.Now() response, err := rootSDK.Get(ctx, "/identity.json?clock="+strconv.FormatInt(started.UnixNano(), 10)) if err != nil || response == nil || response.FromCache { - return cutoffBefore(started) + return watchStart{at: cutoffBefore(started)} } if at, err := http.ParseTime(response.Headers.Get("Date")); err == nil { - return cutoffBefore(at.Add(-time.Since(started))) + return watchStart{at: cutoffBefore(at.Add(-time.Since(started))), onServerClock: true} } - return cutoffBefore(started) + return watchStart{at: cutoffBefore(started)} +} + +// watchStart is the moment a watch began, and whether HEY's clock said so or +// only the workstation's did. +type watchStart struct { + at time.Time + onServerClock bool +} + +// since is where a feed's first read begins, given the since HEY's changes URL +// carries. That since is not HEY's clock: a box's is its last posting activity +// — the latest updated_at among its unbundled postings, or the box's own when +// it has none — and a calendar's is its updated_at, the list's the latest of +// them. The feeds answer changes later than that which are history by now: a +// deletion, a bundled posting, a calendar deleted after the rest last changed. +// Nor is it always even that: the box list comes through the SDK's ETag cache, +// HEY's ETag for it is the box rows, and posting activity does not touch them, +// so a 304 hands back the since as it stood when the list was cached — hours or +// days behind. Read from there, the catch-up reported what came after as news +// on every start, and --exit-on-first stopped on the first of it. +// +// So a feed starts at the watch's start. It reports what happened after it and +// nothing before — including mail that landed after the watch read HEY's clock +// and before it read the box list, which a since later than the start would +// leave behind it, read by nothing; that mail is new, too. +// +// On the workstation's clock alone the start is only as good as that clock, +// and a fast one would put it in HEY's future, where every change until then +// goes unread. There, HEY's own since is kept when it is the earlier of the two +// — or cannot be read — at the cost of the history it may carry: missing mail +// is worse than repeating it. +func (s watchStart) since(served string) string { + start := s.at.UTC().Format(watchCursorTimeLayout) + if s.onServerClock { + return start + } + if at, err := time.Parse(time.RFC3339Nano, served); err == nil && !at.Before(s.at) { + return start + } + + return served } // cutoffBefore makes an instant usable as the watch's start: a cursor is diff --git a/internal/cmd/watch_new_test.go b/internal/cmd/watch_new_test.go index d7b00c90..ec0b2f3a 100644 --- a/internal/cmd/watch_new_test.go +++ b/internal/cmd/watch_new_test.go @@ -20,6 +20,9 @@ import ( var watchStarted = time.Date(2026, 8, 21, 9, 0, 0, 0, time.UTC) +// serverStart is watchStarted as read off HEY's clock. +var serverStart = watchStart{at: watchStarted, onServerClock: true} + func newPosting(id int64, sender, subject string, activeAt time.Time) generated.Posting { return generated.Posting{Id: id, Name: subject, ActiveAt: activeAt, Creator: generated.Contact{Name: sender}} } @@ -226,17 +229,21 @@ func TestServerNowReadsTheServersClock(t *testing.T) { initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) date := time.Date(2026, 8, 21, 9, 0, 5, 0, time.UTC) - got := serverNow(context.Background()) + start := serverNow(context.Background()) + got := start.at // The Date header, less the instant the request took: on the server's // clock, whatever the local one says, and no later than the header. if got.After(date) || date.Sub(got) > time.Second { t.Errorf("serverNow = %v, want the Date header translated back to the request's start", got) } + if !start.onServerClock { + t.Error("a start read off the Date header is on HEY's clock") + } if len(requested) != 1 || !strings.Contains(requested[0], "/identity.json?clock=") { t.Errorf("requested %v, want one uncacheable identity request", requested) } - second := serverNow(context.Background()) + second := serverNow(context.Background()).at if len(requested) != 2 || requested[1] == requested[0] { t.Errorf("requested %v, want a fresh request each time, never the cache", requested) } @@ -262,9 +269,34 @@ func TestCutoffBeforeIsAWholeMillisecondStrictlyBefore(t *testing.T) { if !tracker.isNew(24088, newPosting(101, "Maria Delgado", "Lunch on Thursday?", landed)) { t.Error("mail in the same millisecond as the watch's start is new") } - cursor := startingAt(hey.PostingChangesCursor{Since: landed.Format(watchCursorTimeLayout)}, cutoffBefore(within)) - if cursor.Since != "2026-08-21T09:00:05.122Z" { - t.Errorf("cursor = %q, want it before the millisecond the mail landed in", cursor.Since) + start := watchStart{at: cutoffBefore(within), onServerClock: true} + if since := start.since(landed.Format(watchCursorTimeLayout)); since != "2026-08-21T09:00:05.122Z" { + t.Errorf("since = %q, want it before the millisecond the mail landed in", since) + } +} + +func TestWatchStartSince(t *testing.T) { + earlier := "2026-08-21T08:00:00.518496Z" + later := "2026-08-21T09:00:30.183221Z" + + // On HEY's clock, a feed starts at the start whatever HEY served. + for _, served := range []string{earlier, later, "whenever"} { + if got := serverStart.since(served); got != "2026-08-21T09:00:00.000Z" { + t.Errorf("since(%q) = %q, want the watch's start", served, got) + } + } + + // On the workstation's clock alone the start may be in HEY's future, so it + // never starts later than HEY's own since. + local := watchStart{at: watchStarted} + if got := local.since(earlier); got != earlier { + t.Errorf("since = %q, want HEY's since when it is earlier than a local start", got) + } + if got := local.since(later); got != "2026-08-21T09:00:00.000Z" { + t.Errorf("since = %q, want the start when HEY's since is later", got) + } + if got := local.since("whenever"); got != "whenever" { + t.Errorf("since = %q, want a since that cannot be read left as it is", got) } } @@ -280,7 +312,8 @@ func TestServerNowIsTheClockWhenTheRequestBeganNotWhenItWasAnswered(t *testing.T defer server.Close() initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) - got := serverNow(context.Background()) + start := serverNow(context.Background()) + got := start.at // Mail that lands while the server is answering is later than the start; // a start taken at the Date header would put it before. @@ -334,7 +367,7 @@ func TestWatchReadsMailThatLandedWhileItReadTheClock(t *testing.T) { } watch, out := newTestWatch("added") watch.boxes = boxes - watch.newMail = trackNewMail(started) + watch.newMail = trackNewMail(started.at) if err := watch.catchUp(context.Background()); err != nil { t.Fatalf("unexpected error: %v", err) } @@ -362,7 +395,8 @@ func TestServerNowFallsBackToTheLocalClock(t *testing.T) { initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) before := time.Now() - got := serverNow(context.Background()) + start := serverNow(context.Background()) + got := start.at // The local clock at the request's start, as a cutoff: a whole millisecond, // strictly before — so up to two milliseconds before the instant itself. if got.Before(before.Add(-2*time.Millisecond)) || got.After(time.Now()) { @@ -371,6 +405,9 @@ func TestServerNowFallsBackToTheLocalClock(t *testing.T) { if got.Nanosecond()%int(time.Millisecond) != 0 { t.Errorf("serverNow = %v, want a whole millisecond", got) } + if start.onServerClock { + t.Error("a start the server's clock could not give is not on HEY's clock") + } } // changesServer serves the changes feed bodies in turn, the last one for every diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index 17098885..58a1a269 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -866,7 +866,7 @@ func TestWatchedBoxesStartAtTheWatchsStart(t *testing.T) { initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) command := newWatchCommand() - boxes, err := command.watchedBoxes(context.Background(), watchStarted) + boxes, err := command.watchedBoxes(context.Background(), serverStart) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -882,7 +882,7 @@ func TestWatchedBoxesStartAtTheWatchsStart(t *testing.T) { // --box imbox: every box is still followed, the Imbox alone is reported; // a --box that names nothing is not found. command.boxes = []string{"imbox"} - boxes, err = command.watchedBoxes(context.Background(), watchStarted) + boxes, err = command.watchedBoxes(context.Background(), serverStart) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -890,14 +890,14 @@ func TestWatchedBoxesStartAtTheWatchsStart(t *testing.T) { t.Errorf("boxes = %+v, want both followed and the Imbox alone reported", boxes) } command.boxes = []string{"trailbox"} - if _, err := command.watchedBoxes(context.Background(), watchStarted); err == nil { + if _, err := command.watchedBoxes(context.Background(), serverStart); err == nil { t.Error("expected an error when --box names no box") } command.boxes = nil // --since is the reader's choice and wins over the start. command.since = "2026-08-21T09:30:00Z" - boxes, err = command.watchedBoxes(context.Background(), watchStarted) + boxes, err = command.watchedBoxes(context.Background(), serverStart) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -1025,7 +1025,7 @@ func startWatch(t *testing.T, command *watchCommand, watch *postingsWatch) { t.Fatalf("unexpected error: %v", err) } watch.boxes = boxes - watch.newMail = trackNewMail(started) + watch.newMail = trackNewMail(started.at) if err := watch.catchUp(context.Background()); err != nil { t.Fatalf("unexpected error: %v", err) } From 3152e53bff52e86aa2e067e9509c72dda019d9ea Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 14:46:51 -0400 Subject: [PATCH 04/17] Describe the local-clock start in AGENTS.md The watch notes named startingAt, which is now watchStart.since, and did not say what happens when HEY's clock cannot be read. --- AGENTS.md | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index d5d8726b..afa84d56 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -679,14 +679,17 @@ says (`--box` picks the boxes whose changes are reported; every box is followed) posting recorded as soon as it is classified. The start is the Date header translated back to when the request was made (mail that lands while the server answers is later than the start), it is taken before the box list, and each -box's cursor starts at it (`startingAt`), keeping only the version from the box's +box's cursor starts at it (`watchStart.since`), keeping only the version from the box's `posting_changes_url`. The since HEY puts there is not its clock but the box's last posting activity (`Box#last_posting_activity_at`: unbundled postings only, the box's own `updated_at` when it has none), and the feed answers deletions and bundled postings later than that; and `/boxes.json` comes through the SDK's ETag cache with an ETag of the box rows alone, which posting activity does not touch, so a 304 serves the since as it was when the list was cached. A read from HEY's since reported history as news on every start, and a since later -than the start would leave mail that landed in between behind it, read by nothing. That +than the start would leave mail that landed in between behind it, read by nothing. When +HEY's clock cannot be read the start is the workstation's (`watchStart.onServerClock` is +false), which may be in HEY's future, so HEY's since is kept when it is earlier — missing +mail is worse than repeating it. That is HEY's semantics and state across events, so the CLI decides it once; what to do about it is the reader's. A 409 skip-ahead sets that box's floor at the cursor it skipped to (`newMail.skippedTo`): activity at or before it is never new there, known thread or not, From c78d7625ed7cccb649051bd87a0409ca29275b3f Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 14:59:07 -0400 Subject: [PATCH 05/17] Refuse to start a watch without HEY's clock MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The previous commit kept HEY's cursor when only the workstation's clock said when a watch began, but new mail is measured against that same start: a fast clock would still call mail that arrived after startup old, and a slow one would call replayed history new, and the docs promised a start that the fallback did not keep. serverNow now returns an error when HEY's clock cannot be read — the request failed, or the answer carried no Date header — and the watch exits with it rather than guess. A request that fails there would fail at the box list next anyway. Every feed starts at the start again (watchStartSince), with no second rule to describe. --- AGENTS.md | 10 +-- docs/cli.md | 4 +- docs/omarchy.md | 3 +- internal/cmd/watch.go | 13 ++-- internal/cmd/watch_calendar.go | 10 +-- internal/cmd/watch_calendar_test.go | 4 +- internal/cmd/watch_new.go | 88 ++++++++++++-------------- internal/cmd/watch_new_test.go | 95 +++++++++++------------------ internal/cmd/watch_test.go | 12 ++-- 9 files changed, 107 insertions(+), 132 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index afa84d56..ffb57e00 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -679,17 +679,17 @@ says (`--box` picks the boxes whose changes are reported; every box is followed) posting recorded as soon as it is classified. The start is the Date header translated back to when the request was made (mail that lands while the server answers is later than the start), it is taken before the box list, and each -box's cursor starts at it (`watchStart.since`), keeping only the version from the box's +box's cursor starts at it (`watchStartSince`), keeping only the version from the box's `posting_changes_url`. The since HEY puts there is not its clock but the box's last posting activity (`Box#last_posting_activity_at`: unbundled postings only, the box's own `updated_at` when it has none), and the feed answers deletions and bundled postings later than that; and `/boxes.json` comes through the SDK's ETag cache with an ETag of the box rows alone, which posting activity does not touch, so a 304 serves the since as it was when the list was cached. A read from HEY's since reported history as news on every start, and a since later -than the start would leave mail that landed in between behind it, read by nothing. When -HEY's clock cannot be read the start is the workstation's (`watchStart.onServerClock` is -false), which may be in HEY's future, so HEY's since is kept when it is earlier — missing -mail is worse than repeating it. That +than the start would leave mail that landed in between behind it, read by nothing. A watch +that cannot read HEY's clock does not start: the workstation's clock is no stand-in for a +cutoff every feed and new mail are measured against, since a fast one would skip changes and +a slow one would report history. That is HEY's semantics and state across events, so the CLI decides it once; what to do about it is the reader's. A 409 skip-ahead sets that box's floor at the cursor it skipped to (`newMail.skippedTo`): activity at or before it is never new there, known thread or not, diff --git a/docs/cli.md b/docs/cli.md index 80249ce6..21c121f4 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -338,7 +338,9 @@ hey watch --run-sync ./triage.sh # one at a time, waiting for each Runs until interrupted, printing changes as they happen, one line each. What changed before the watch began is not reported unless `--since` reads back to it first, so -`--exit-on-first` waits for a change rather than stopping on an old one: +`--exit-on-first` waits for a change rather than stopping on an old one. When the watch began +is read off HEY's clock, and a watch that cannot read it exits with an error rather than +guess: ```json {"change":"added","at":"2026-08-18T09:14:22.031Z","box":{"id":24088,"kind":"imbox","name":"Imbox"},"posting_id":98765,"thread_id":54321,"new":true,"posting":{}} diff --git a/docs/omarchy.md b/docs/omarchy.md index ef347be2..83417b9f 100644 --- a/docs/omarchy.md +++ b/docs/omarchy.md @@ -191,7 +191,8 @@ and `--events new` selects the true ones. The rule: watch last recorded for the thread — or later than the watch's start, when it has no record. That start is read off HEY's own clock (the `Date` header of one request, translated back to the moment the request was made), the clock every `active_at` is on, - so a workstation running fast or slow neither calls the backlog new nor sits on new mail; + so a workstation running fast or slow neither calls the backlog new nor sits on new mail + (a watch that cannot read HEY's clock exits with an error rather than use its own); whole seconds, rounded down, so the doubt falls on the side of calling mail a moment old new, and every box's cursor starts at that start, so mail that lands while the watch is starting up is read and is new. `active_at` moves on new mail only, not on a diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index d98e24d9..6283b82a 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -153,8 +153,11 @@ func (c *watchCommand) run(cmd *cobra.Command, args []string) error { // New mail is measured against the watch's start, so that is taken before // the boxes' cursors are read — and the cursors start at it, so nothing // that lands between the two sits behind a cursor, read by nothing. - started := serverNow(ctx) - newMail := trackNewMail(started.at) + started, err := serverNow(ctx) + if err != nil { + return err + } + newMail := trackNewMail(started) boxes, err := c.watchedBoxes(ctx, started) if err != nil { @@ -253,7 +256,7 @@ func (c *watchCommand) watchedChanges() (map[string]bool, error) { return changes, nil } -func (c *watchCommand) watchedBoxes(ctx context.Context, started watchStart) (map[int64]*watchedBox, error) { +func (c *watchCommand) watchedBoxes(ctx context.Context, started time.Time) (map[int64]*watchedBox, error) { listed, err := sdk.Boxes().List(ctx) if err != nil { return nil, apierr.FromSDK(err) @@ -277,7 +280,7 @@ func (c *watchCommand) watchedBoxes(ctx context.Context, started watchStart) (ma continue } if c.since == "" { - cursor.Since = started.since(cursor.Since) + cursor.Since = watchStartSince(started) } watched[box.Id] = &watchedBox{id: box.Id, kind: box.Kind, name: box.Name, cursor: cursor, reported: c.watching(box)} @@ -309,7 +312,7 @@ func boxIs(box generated.Box, wanted string) bool { // watchCursor reads the cursor out of a box's changes URL — HEY's own, which a skip-ahead // resumes from — unless --since moves it. Without --since, a watch's first read starts -// at the watch's start instead (watchStart.since). +// at the watch's start instead (watchStartSince). func watchCursor(changesURL, since string) (hey.PostingChangesCursor, error) { if changesURL == "" { return hey.PostingChangesCursor{}, nil diff --git a/internal/cmd/watch_calendar.go b/internal/cmd/watch_calendar.go index 40f0387f..9af9a917 100644 --- a/internal/cmd/watch_calendar.go +++ b/internal/cmd/watch_calendar.go @@ -79,11 +79,11 @@ func (c *watchCommand) watchingCalendars(changes map[string]bool) bool { } // watchedCalendars reads the calendars and where each one's feed should be read from. The -// cursors start at the watch's start the way the boxes' do (watchStart.since): the since +// cursors start at the watch's start the way the boxes' do (watchStartSince): the since // HEY serves is a calendar's own updated_at — for the list, the latest of them — so a // calendar deleted after the rest last changed was reported by the first poll of every // watch. -func (c *watchCommand) watchedCalendars(ctx context.Context, started watchStart) (*calendarsWatch, error) { +func (c *watchCommand) watchedCalendars(ctx context.Context, started time.Time) (*calendarsWatch, error) { list, err := sdk.Calendars().ListWithChanges(ctx) if err != nil { return nil, apierr.FromSDK(err) @@ -116,7 +116,7 @@ func (c *watchCommand) watchedCalendars(ctx context.Context, started watchStart) return watch, nil } -func (c *watchCommand) followedCalendar(listed hey.ListedCalendar, started watchStart) (*watchedCalendar, error) { +func (c *watchCommand) followedCalendar(listed hey.ListedCalendar, started time.Time) (*watchedCalendar, error) { cursor, err := c.calendarCursor(listed.RecordingChangesURL, started) if err != nil { return nil, err @@ -132,13 +132,13 @@ func (c *watchCommand) followedCalendar(listed hey.ListedCalendar, started watch // calendarCursor is where a feed should be read from: the feed and version the URL HEY // served names, from --since or else from the watch's start. -func (c *watchCommand) calendarCursor(changesURL string, started watchStart) (hey.CalendarChangesCursor, error) { +func (c *watchCommand) calendarCursor(changesURL string, started time.Time) (hey.CalendarChangesCursor, error) { cursor, err := hey.CalendarChangesCursorFrom(changesURL) if err != nil { return hey.CalendarChangesCursor{}, apierr.FromSDK(err) } if c.since == "" { - cursor.Since = started.since(cursor.Since) + cursor.Since = watchStartSince(started) return cursor, nil } diff --git a/internal/cmd/watch_calendar_test.go b/internal/cmd/watch_calendar_test.go index fd3cd34f..a246af07 100644 --- a/internal/cmd/watch_calendar_test.go +++ b/internal/cmd/watch_calendar_test.go @@ -53,7 +53,7 @@ func TestWatchingCalendars(t *testing.T) { func TestCalendarCursor(t *testing.T) { changesURL := "https://app.hey.com/calendars/512/recording/changes.json?since=2026-08-18T09%3A00%3A00.000Z&v=1" - started := watchStart{at: time.Date(2026, 8, 18, 10, 0, 0, 0, time.UTC), onServerClock: true} + started := time.Date(2026, 8, 18, 10, 0, 0, 0, time.UTC) command := newWatchCommand() cursor, err := command.calendarCursor(changesURL, started) @@ -128,7 +128,7 @@ func TestWatchPollDoesNotReportHistoryAsItStarts(t *testing.T) { defer server.Close() initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) - calendars, err := newWatchCommand().watchedCalendars(context.Background(), serverStart) + calendars, err := newWatchCommand().watchedCalendars(context.Background(), watchStarted) if err != nil { t.Fatalf("unexpected error: %v", err) } diff --git a/internal/cmd/watch_new.go b/internal/cmd/watch_new.go index e9c3e8da..4faac201 100644 --- a/internal/cmd/watch_new.go +++ b/internal/cmd/watch_new.go @@ -8,6 +8,8 @@ import ( "github.com/basecamp/hey-sdk/go/pkg/generated" hey "github.com/basecamp/hey-sdk/go/pkg/hey" + + "github.com/basecamp/hey-cli/internal/apierr" ) // New mail is a watch event: every added and updated line says whether the @@ -17,7 +19,7 @@ import ( // what to do about it (a toast, a bell, a re-read) is the reader's. // // There is no state file: new means active since the watch began, so the -// backlog a box's first read carries is not new, and what the watch remembers — +// backlog --since reads is not new, and what the watch remembers — // when each thread was last active — lives and dies with it. // newMail keeps up with every thread the watch reads, in every box and whatever @@ -68,61 +70,51 @@ func (n *newMail) skippedTo(boxID int64, cursor hey.PostingChangesCursor) { // earlier. Date is whole seconds, rounded down, which errs the same way: towards // calling mail a moment old new rather than mail a moment new old. The SDK // caches GETs by URL, so a query the server ignores keeps this one out of the -// cache; and when the server's clock can't be read, the local clock at the -// start stands in, and the start says so. Either way it is handed out as a -// cutoff: a whole millisecond, strictly before the instant it stands for. -func serverNow(ctx context.Context) watchStart { +// cache. The start is handed out as a cutoff: a whole millisecond, strictly +// before the instant it stands for. +// +// A watch that cannot read HEY's clock does not start. The workstation's clock +// is no stand-in: every feed starts at the start (watchStartSince) and new mail +// is measured against it, so a fast clock would put both in HEY's future — +// changes unread and new mail called old until the clocks met — and a slow one +// would report history. A request that fails here would fail at the box list +// next anyway. +func serverNow(ctx context.Context) (time.Time, error) { started := time.Now() response, err := rootSDK.Get(ctx, "/identity.json?clock="+strconv.FormatInt(started.UnixNano(), 10)) - if err != nil || response == nil || response.FromCache { - return watchStart{at: cutoffBefore(started)} + if err != nil { + return time.Time{}, apierr.FromSDK(err) } - if at, err := http.ParseTime(response.Headers.Get("Date")); err == nil { - return watchStart{at: cutoffBefore(at.Add(-time.Since(started))), onServerClock: true} + if response == nil || response.FromCache { + return time.Time{}, apierr.ErrAPI(0, "could not read HEY's clock — the watch needs it to tell what happened after it began") + } + at, err := http.ParseTime(response.Headers.Get("Date")) + if err != nil { + return time.Time{}, apierr.ErrAPI(0, "HEY's answer carried no Date header — the watch needs HEY's clock to tell what happened after it began") } - return watchStart{at: cutoffBefore(started)} -} - -// watchStart is the moment a watch began, and whether HEY's clock said so or -// only the workstation's did. -type watchStart struct { - at time.Time - onServerClock bool + return cutoffBefore(at.Add(-time.Since(started))), nil } -// since is where a feed's first read begins, given the since HEY's changes URL -// carries. That since is not HEY's clock: a box's is its last posting activity -// — the latest updated_at among its unbundled postings, or the box's own when -// it has none — and a calendar's is its updated_at, the list's the latest of -// them. The feeds answer changes later than that which are history by now: a -// deletion, a bundled posting, a calendar deleted after the rest last changed. -// Nor is it always even that: the box list comes through the SDK's ETag cache, -// HEY's ETag for it is the box rows, and posting activity does not touch them, -// so a 304 hands back the since as it stood when the list was cached — hours or -// days behind. Read from there, the catch-up reported what came after as news -// on every start, and --exit-on-first stopped on the first of it. +// watchStartSince is where a feed's first read begins without --since: the +// watch's start, in place of the since HEY's changes URL carries. That since is +// not HEY's clock. A box's is its last posting activity — the latest updated_at +// among its unbundled postings, or the box's own when it has none — and a +// calendar's is its updated_at, the list's the latest of them; the feeds answer +// changes later than that which are history by now: a deletion, a bundled +// posting, a calendar deleted after the rest last changed. Nor is it always +// even that: the box list comes through the SDK's ETag cache, HEY's ETag for it +// is the box rows, and posting activity does not touch them, so a 304 hands +// back the since as it stood when the list was cached — hours or days behind. +// Read from there, the catch-up reported what came after as news on every +// start, and --exit-on-first stopped on the first of it. // -// So a feed starts at the watch's start. It reports what happened after it and -// nothing before — including mail that landed after the watch read HEY's clock -// and before it read the box list, which a since later than the start would -// leave behind it, read by nothing; that mail is new, too. -// -// On the workstation's clock alone the start is only as good as that clock, -// and a fast one would put it in HEY's future, where every change until then -// goes unread. There, HEY's own since is kept when it is the earlier of the two -// — or cannot be read — at the cost of the history it may carry: missing mail -// is worse than repeating it. -func (s watchStart) since(served string) string { - start := s.at.UTC().Format(watchCursorTimeLayout) - if s.onServerClock { - return start - } - if at, err := time.Parse(time.RFC3339Nano, served); err == nil && !at.Before(s.at) { - return start - } - - return served +// From the start a feed reports what happened after it and nothing before — +// including mail that landed after the watch read HEY's clock and before it +// read the box list, which a since later than the start would leave behind it, +// read by nothing; that mail is new, too. +func watchStartSince(started time.Time) string { + return started.UTC().Format(watchCursorTimeLayout) } // cutoffBefore makes an instant usable as the watch's start: a cursor is diff --git a/internal/cmd/watch_new_test.go b/internal/cmd/watch_new_test.go index ec0b2f3a..27ee263b 100644 --- a/internal/cmd/watch_new_test.go +++ b/internal/cmd/watch_new_test.go @@ -20,8 +20,15 @@ import ( var watchStarted = time.Date(2026, 8, 21, 9, 0, 0, 0, time.UTC) -// serverStart is watchStarted as read off HEY's clock. -var serverStart = watchStart{at: watchStarted, onServerClock: true} +// readServerNow is serverNow where the test's server answers with its clock. +func readServerNow(t *testing.T) time.Time { + t.Helper() + started, err := serverNow(context.Background()) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + return started +} func newPosting(id int64, sender, subject string, activeAt time.Time) generated.Posting { return generated.Posting{Id: id, Name: subject, ActiveAt: activeAt, Creator: generated.Contact{Name: sender}} @@ -50,9 +57,8 @@ func TestNewMailIsSinceTheWatchBeganNotTheBacklog(t *testing.T) { before := watchStarted.Add(-time.Hour) after := watchStarted.Add(30 * time.Second) - // A box's first read carries everything since the server's cursor — the - // box's last activity — which may be hours of backlog, plus mail that - // arrived while the watch was starting up. + // A read from --since carries backlog, alongside mail that arrived while + // the watch was starting up. backlog := newPosting(101, "Maria Delgado", "Lunch on Thursday?", before) arrived := newPosting(102, "Northwind Invoicing", "Invoice #4021", after) if fresh := classifyRead(tracker, backlog, arrived); len(fresh) != 1 || fresh[0] != 102 { @@ -229,21 +235,17 @@ func TestServerNowReadsTheServersClock(t *testing.T) { initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) date := time.Date(2026, 8, 21, 9, 0, 5, 0, time.UTC) - start := serverNow(context.Background()) - got := start.at + got := readServerNow(t) // The Date header, less the instant the request took: on the server's // clock, whatever the local one says, and no later than the header. if got.After(date) || date.Sub(got) > time.Second { t.Errorf("serverNow = %v, want the Date header translated back to the request's start", got) } - if !start.onServerClock { - t.Error("a start read off the Date header is on HEY's clock") - } if len(requested) != 1 || !strings.Contains(requested[0], "/identity.json?clock=") { t.Errorf("requested %v, want one uncacheable identity request", requested) } - second := serverNow(context.Background()).at + second := readServerNow(t) if len(requested) != 2 || requested[1] == requested[0] { t.Errorf("requested %v, want a fresh request each time, never the cache", requested) } @@ -269,37 +271,11 @@ func TestCutoffBeforeIsAWholeMillisecondStrictlyBefore(t *testing.T) { if !tracker.isNew(24088, newPosting(101, "Maria Delgado", "Lunch on Thursday?", landed)) { t.Error("mail in the same millisecond as the watch's start is new") } - start := watchStart{at: cutoffBefore(within), onServerClock: true} - if since := start.since(landed.Format(watchCursorTimeLayout)); since != "2026-08-21T09:00:05.122Z" { + if since := watchStartSince(cutoffBefore(within)); since != "2026-08-21T09:00:05.122Z" { t.Errorf("since = %q, want it before the millisecond the mail landed in", since) } } -func TestWatchStartSince(t *testing.T) { - earlier := "2026-08-21T08:00:00.518496Z" - later := "2026-08-21T09:00:30.183221Z" - - // On HEY's clock, a feed starts at the start whatever HEY served. - for _, served := range []string{earlier, later, "whenever"} { - if got := serverStart.since(served); got != "2026-08-21T09:00:00.000Z" { - t.Errorf("since(%q) = %q, want the watch's start", served, got) - } - } - - // On the workstation's clock alone the start may be in HEY's future, so it - // never starts later than HEY's own since. - local := watchStart{at: watchStarted} - if got := local.since(earlier); got != earlier { - t.Errorf("since = %q, want HEY's since when it is earlier than a local start", got) - } - if got := local.since(later); got != "2026-08-21T09:00:00.000Z" { - t.Errorf("since = %q, want the start when HEY's since is later", got) - } - if got := local.since("whenever"); got != "whenever" { - t.Errorf("since = %q, want a since that cannot be read left as it is", got) - } -} - func TestServerNowIsTheClockWhenTheRequestBeganNotWhenItWasAnswered(t *testing.T) { t.Setenv("HEY_TOKEN", "test-token") const delay = 300 * time.Millisecond @@ -312,8 +288,7 @@ func TestServerNowIsTheClockWhenTheRequestBeganNotWhenItWasAnswered(t *testing.T defer server.Close() initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) - start := serverNow(context.Background()) - got := start.at + got := readServerNow(t) // Mail that lands while the server is answering is later than the start; // a start taken at the Date header would put it before. @@ -359,7 +334,7 @@ func TestWatchReadsMailThatLandedWhileItReadTheClock(t *testing.T) { initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) // As run does: the clock, then the boxes, then the catch-up. - started := serverNow(context.Background()) + started := readServerNow(t) command := newWatchCommand() boxes, err := command.watchedBoxes(context.Background(), started) if err != nil { @@ -367,7 +342,7 @@ func TestWatchReadsMailThatLandedWhileItReadTheClock(t *testing.T) { } watch, out := newTestWatch("added") watch.boxes = boxes - watch.newMail = trackNewMail(started.at) + watch.newMail = trackNewMail(started) if err := watch.catchUp(context.Background()); err != nil { t.Fatalf("unexpected error: %v", err) } @@ -386,27 +361,29 @@ func TestWatchReadsMailThatLandedWhileItReadTheClock(t *testing.T) { } } -func TestServerNowFallsBackToTheLocalClock(t *testing.T) { +// A watch that cannot read HEY's clock does not start: the workstation's clock is +// no stand-in for the cutoff every feed and new mail are measured against. +func TestServerNowRefusesWithoutHEYsClock(t *testing.T) { t.Setenv("HEY_TOKEN", "test-token") - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + + down := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { http.Error(w, "down", http.StatusBadGateway) })) - defer server.Close() - initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) - - before := time.Now() - start := serverNow(context.Background()) - got := start.at - // The local clock at the request's start, as a cutoff: a whole millisecond, - // strictly before — so up to two milliseconds before the instant itself. - if got.Before(before.Add(-2*time.Millisecond)) || got.After(time.Now()) { - t.Errorf("serverNow = %v, want the local clock at the start when the server's can't be read", got) + defer down.Close() + initSDK(auth.NewManager(down.URL, down.Client(), t.TempDir()), down.URL) + if _, err := serverNow(context.Background()); err == nil { + t.Error("expected an error when HEY cannot be reached") } - if got.Nanosecond()%int(time.Millisecond) != 0 { - t.Errorf("serverNow = %v, want a whole millisecond", got) - } - if start.onServerClock { - t.Error("a start the server's clock could not give is not on HEY's clock") + + undated := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{"id":1}`)) + })) + defer undated.Close() + initSDK(auth.NewManager(undated.URL, undated.Client(), t.TempDir()), undated.URL) + if _, err := serverNow(context.Background()); err == nil { + t.Error("expected an error when HEY's answer carries no Date header") } } diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index 58a1a269..92a393f7 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -866,7 +866,7 @@ func TestWatchedBoxesStartAtTheWatchsStart(t *testing.T) { initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) command := newWatchCommand() - boxes, err := command.watchedBoxes(context.Background(), serverStart) + boxes, err := command.watchedBoxes(context.Background(), watchStarted) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -882,7 +882,7 @@ func TestWatchedBoxesStartAtTheWatchsStart(t *testing.T) { // --box imbox: every box is still followed, the Imbox alone is reported; // a --box that names nothing is not found. command.boxes = []string{"imbox"} - boxes, err = command.watchedBoxes(context.Background(), serverStart) + boxes, err = command.watchedBoxes(context.Background(), watchStarted) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -890,14 +890,14 @@ func TestWatchedBoxesStartAtTheWatchsStart(t *testing.T) { t.Errorf("boxes = %+v, want both followed and the Imbox alone reported", boxes) } command.boxes = []string{"trailbox"} - if _, err := command.watchedBoxes(context.Background(), serverStart); err == nil { + if _, err := command.watchedBoxes(context.Background(), watchStarted); err == nil { t.Error("expected an error when --box names no box") } command.boxes = nil // --since is the reader's choice and wins over the start. command.since = "2026-08-21T09:30:00Z" - boxes, err = command.watchedBoxes(context.Background(), serverStart) + boxes, err = command.watchedBoxes(context.Background(), watchStarted) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -1019,13 +1019,13 @@ func (h *heyHistory) serveChanges(w http.ResponseWriter, boxID int64, since stri // catch-up. func startWatch(t *testing.T, command *watchCommand, watch *postingsWatch) { t.Helper() - started := serverNow(context.Background()) + started := readServerNow(t) boxes, err := command.watchedBoxes(context.Background(), started) if err != nil { t.Fatalf("unexpected error: %v", err) } watch.boxes = boxes - watch.newMail = trackNewMail(started.at) + watch.newMail = trackNewMail(started) if err := watch.catchUp(context.Background()); err != nil { t.Fatalf("unexpected error: %v", err) } From a4628e04689a0b89f0179841307c1a179efdfe7b Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 15:21:25 -0400 Subject: [PATCH 06/17] Say that a watch's start can be up to a second early MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit HEY's Date header is whole seconds, so the start read off it can be up to a second — plus the request's own time — before the watch really began, and a change from that window is read, reported, can be new, and can end --exit-on-first. Nothing HEY serves says the time any finer: Action Cable's pings carry Time.now.to_i, no JSON answer carries a server "now", and the one sync URL built from the clock (a box's next_incremental_sync_url) is whole seconds too. Rounding the other way would skip up to a second of changes that came after the start, which is worse than repeating one that did not. The help text, docs/cli.md, docs/omarchy.md, the skill and AGENTS.md now say so, and a test pins the boundary: a change in the Date header's own second is reported, with its at, and one from before it is not. --- AGENTS.md | 5 ++++- docs/cli.md | 4 +++- docs/omarchy.md | 3 ++- internal/cmd/watch.go | 4 +++- internal/cmd/watch_new.go | 18 ++++++++++++------ internal/cmd/watch_test.go | 31 +++++++++++++++++++++++++------ skills/hey/SKILL.md | 3 ++- 7 files changed, 51 insertions(+), 17 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index ffb57e00..1a7ad68d 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -691,7 +691,10 @@ that cannot read HEY's clock does not start: the workstation's clock is no stand cutoff every feed and new mail are measured against, since a fast one would skip changes and a slow one would report history. That is HEY's semantics and state across events, so the CLI decides it once; what to do about -it is the reader's. A 409 skip-ahead sets that box's floor at the cursor it skipped to +it is the reader's. The Date header is whole seconds, so the start can be up to a second +(plus the request's time) early and a change from that window is reported; nothing HEY +serves says the time finer — Action Cable pings are whole seconds too — and rounding the +other way would skip changes. A 409 skip-ahead sets that box's floor at the cursor it skipped to (`newMail.skippedTo`): activity at or before it is never new there, known thread or not, because the watch never read the gap. `resync` is an event of its own — reported by default, left out by `--events new` — so a script for new mail never runs on one. The Omarchy bar plugin toasts from those lines itself (app-name, glyph, diff --git a/docs/cli.md b/docs/cli.md index 21c121f4..19914b72 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -340,7 +340,9 @@ Runs until interrupted, printing changes as they happen, one line each. What cha the watch began is not reported unless `--since` reads back to it first, so `--exit-on-first` waits for a change rather than stopping on an old one. When the watch began is read off HEY's clock, and a watch that cannot read it exits with an error rather than -guess: +guess. That clock is read to the whole second, so a change from up to about a second before +the watch began can still be reported (and be new, and end `--exit-on-first`); its `at` says +when it happened. Rounding the other way would skip changes that came after: ```json {"change":"added","at":"2026-08-18T09:14:22.031Z","box":{"id":24088,"kind":"imbox","name":"Imbox"},"posting_id":98765,"thread_id":54321,"new":true,"posting":{}} diff --git a/docs/omarchy.md b/docs/omarchy.md index 83417b9f..4311d4b8 100644 --- a/docs/omarchy.md +++ b/docs/omarchy.md @@ -194,7 +194,8 @@ and `--events new` selects the true ones. The rule: so a workstation running fast or slow neither calls the backlog new nor sits on new mail (a watch that cannot read HEY's clock exits with an error rather than use its own); whole seconds, rounded down, so the doubt falls on the side of calling mail a moment old - new, and every box's cursor starts at that start, so mail that lands while the + new — mail from up to about a second before the watch began can read as new — and every + box's cursor starts at that start, so mail that lands while the watch is starting up is read and is new. `active_at` moves on new mail only, not on a seen flip, a mute or a move, so reading a thread, marking it unseen again or moving it into a box is never new, and a reply on a known thread is. A box's first read starts at diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index 6283b82a..c4c3196f 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -74,7 +74,9 @@ func newWatchCommand() *watchCommand { Short: "Follow email threads and calendars as they change", Long: `Print email threads and calendar changes as they happen: piped or with --json, one JSON object per line; at a terminal, one text line each. Runs until interrupted. What -changed before the watch began is not reported, unless --since reads back to it first. +changed before the watch began is not reported, unless --since reads back to it first — +save a change from up to about a second before, since HEY's clock is read to the whole +second; its "at" says when it happened. Changes can drive a command instead of being printed, and that is a choice between two behaviours: --run-async spawns the command per change and moves on, so a slow one never diff --git a/internal/cmd/watch_new.go b/internal/cmd/watch_new.go index 4faac201..fcf76eac 100644 --- a/internal/cmd/watch_new.go +++ b/internal/cmd/watch_new.go @@ -68,10 +68,17 @@ func (n *newMail) skippedTo(boxID int64, cursor hey.PostingChangesCursor) { // the request took — the local monotonic clock, which a wrong wall clock does // not touch — and a slow request, or one the SDK retried, only moves the start // earlier. Date is whole seconds, rounded down, which errs the same way: towards -// calling mail a moment old new rather than mail a moment new old. The SDK -// caches GETs by URL, so a query the server ignores keeps this one out of the -// cache. The start is handed out as a cutoff: a whole millisecond, strictly -// before the instant it stands for. +// calling mail a moment old new rather than mail a moment new old. That is a +// window of up to a second, plus the request's own time: a change from that +// long before the watch began is after the start, so it is read, reported and +// can be new, and --exit-on-first can stop on it. Nothing HEY serves says the +// time any finer — Action Cable's pings are whole seconds too, and no JSON +// answer carries a server "now" — and rounding the other way would skip up to +// a second of changes that did come after the start, which is worse than +// repeating one that did not. A reader who cares can tell from the line's at. +// The SDK caches GETs by URL, so a query the server ignores keeps this one out +// of the cache. The start is handed out as a cutoff: a whole millisecond, +// strictly before the instant it stands for. // // A watch that cannot read HEY's clock does not start. The workstation's clock // is no stand-in: every feed starts at the start (watchStartSince) and new mail @@ -130,8 +137,7 @@ func cutoffBefore(at time.Time) time.Time { // isNew says whether a posting is new mail: unseen, not muted, and active since // this watch last saw the thread — or since the watch began, for a thread it // has no record of, because anything active before that was already there: the -// backlog a box's first read carries from the server's cursor, or a thread that -// merely moved in. active_at moves on new mail only, not when a thread is read, +// backlog --since reads, or a thread that merely moved in. active_at moves on new mail only, not when a thread is read, // muted or moved, so none of those is new and a reply on a known thread is. func (n *newMail) isNew(boxID int64, posting generated.Posting) bool { last, known := n.activeAt[posting.Id] diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index 92a393f7..1f80a0a0 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -953,12 +953,12 @@ func newHEYHistory(t *testing.T) *heyHistory { return history } -// land is a change arriving at HEY, whose box's cursor is now its last activity. -func (h *heyHistory) land(boxID int64, change historyChange) { +// land is a change arriving in the Imbox, whose cursor is now its last activity. +func (h *heyHistory) land(change historyChange) { h.mu.Lock() defer h.mu.Unlock() - h.changes[boxID] = append(h.changes[boxID], change) - h.cursors[boxID] = change.at + h.changes[24088] = append(h.changes[24088], change) + h.cursors[24088] = change.at } func (h *heyHistory) serve(w http.ResponseWriter, r *http.Request) { @@ -1047,7 +1047,7 @@ func TestWatchDoesNotReportHistoryAsItStarts(t *testing.T) { } // A reply lands after the watch began: that is the change it was waiting for. - history.land(24088, historyChange{at: "2026-08-21T09:00:12.250000Z", id: 9003, subject: "Re: Lunch on Thursday?"}) + history.land(historyChange{at: "2026-08-21T09:00:12.250000Z", id: 9003, subject: "Re: Lunch on Thursday?"}) ringBox(t, watch) lines = watchLines(t, out) @@ -1064,7 +1064,7 @@ func TestWatchReadsMailThatLandedBeforeItReadTheBoxes(t *testing.T) { // The watch reads HEY's clock a moment before the Date header; this lands on the // header's second, after the start and before the box list, so the Imbox's cursor is // already past it. - history.land(24088, historyChange{at: "2026-08-21T09:00:05.000000Z", id: 9003, subject: "Invoice #4021"}) + history.land(historyChange{at: "2026-08-21T09:00:05.000000Z", id: 9003, subject: "Invoice #4021"}) watch, out := newTestWatch(defaultChanges...) startWatch(t, newWatchCommand(), watch) @@ -1075,6 +1075,25 @@ func TestWatchReadsMailThatLandedBeforeItReadTheBoxes(t *testing.T) { } } +// HEY's clock is read to the whole second, so the watch cannot tell a change from the +// Date header's own second that came before it from one that came after, and it reads +// both: skipping one that came after would be worse than repeating one that did not. +// Anything earlier than the second the watch read — less the request's time — is +// behind the start and not reported. +func TestWatchReadsTheWholeSecondHEYsClockWasReadIn(t *testing.T) { + history := newHEYHistory(t) + history.land(historyChange{at: "2026-08-21T09:00:03.990000Z", id: 9003, subject: "Invoice #4021"}) + history.land(historyChange{at: "2026-08-21T09:00:05.200000Z", id: 9004, subject: "Re: Invoice #4021"}) + watch, out := newTestWatch(defaultChanges...) + + startWatch(t, newWatchCommand(), watch) + + lines := watchLines(t, out) + if len(lines) != 2 || lines[0]["posting_id"] != float64(9004) || lines[0]["at"] != "2026-08-21T09:00:05.200Z" || lines[0]["new"] != true || lines[1]["change"] != "ready" { + t.Errorf("wrote %v, want the change from the Date header's second, with when it happened, and not the one before it", lines) + } +} + func TestWatchSinceReadsTheHistoryFirst(t *testing.T) { newHEYHistory(t) command := newWatchCommand() diff --git a/skills/hey/SKILL.md b/skills/hey/SKILL.md index a752623d..03adad1e 100644 --- a/skills/hey/SKILL.md +++ b/skills/hey/SKILL.md @@ -716,7 +716,8 @@ stdout, one per line, instead of the usual envelope (at a terminal, one text lin the posting is new mail — unseen, not muted, and active since the watch last saw the thread, or since the watch began for a thread it has not seen; the backlog `--since` reads is never new, nor is reading, muting or moving a thread, and a reply on a known thread is. -Without `--since`, nothing from before the watch began is reported at all. +Without `--since`, nothing from before the watch began is reported, save a change from up to +about a second before (HEY's clock is read to the whole second); its `at` says when it happened. `--events new` selects the new ones, alone or in a union with the other three. A deleted posting carries no `posting`, `thread_id` or `new`. Three more lines describe the watch itself: `{"change": "ready"}` once every box and calendar is caught up and the subscription From 24b299e757443d7e0c92127c1e884a95cc2a6cdb Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 15:22:33 -0400 Subject: [PATCH 07/17] Skip a box that fell behind to HEY's clock, not its listed cursor A read that answers 409 skipped ahead to the since in the box's posting_changes_url, read from a fresh box list. The list comes through the SDK's ETag cache, and HEY's ETag for /boxes.json is the box rows, which posting activity never touches: after a drop long enough for 2,000 changes, the 304 handed back the since the watch had fallen behind from, the next read answered 409 again, and every doorbell after that was another resync that did not advance. Even a fresh since is the box's last posting activity, which a deletion or a bundled posting can come later than. A skip-ahead now moves the cursor to HEY's clock at the skip, read the way the watch's start is, keeping the feed's version from the box's URL. The box list is still read for that version and to learn whether the box is gone. The resync line's at is the skip point, and so is the box's new-mail floor. A clock that cannot be read leaves the cursor where it was, to be tried again on the retry backoff, as any failed read is. A calendar's 409 skips the same way. Its list is not stale the same way, since a recording touches its calendar and so the list's ETag, but its since is still the calendar's updated_at rather than HEY's clock, and one rule is easier to reason about than two. --- AGENTS.md | 10 ++- docs/omarchy.md | 4 +- internal/cmd/watch.go | 59 +++++++++---- internal/cmd/watch_calendar.go | 49 +++++++---- internal/cmd/watch_calendar_test.go | 19 ++++- internal/cmd/watch_new.go | 11 +-- internal/cmd/watch_test.go | 126 +++++++++++++++++++++++++--- 7 files changed, 220 insertions(+), 58 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 1a7ad68d..16668f6c 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -694,9 +694,11 @@ is HEY's semantics and state across events, so the CLI decides it once; what to it is the reader's. The Date header is whole seconds, so the start can be up to a second (plus the request's time) early and a change from that window is reported; nothing HEY serves says the time finer — Action Cable pings are whole seconds too — and rounding the -other way would skip changes. A 409 skip-ahead sets that box's floor at the cursor it skipped to -(`newMail.skippedTo`): activity at or before it is never new there, known thread or not, -because the watch never read the gap. `resync` is an event of its own — reported by default, +other way would skip changes. A 409 skip-ahead moves the cursor to HEY's clock now +(`serverNow`, not the box list's since, which the ETag cache can serve unchanged and would +409 again) and sets that box's floor there (`newMail.skippedTo`): activity at or before it +is never new there, known thread or not, because the watch never read the gap. A calendar's +409 skips the same way. `resync` is an event of its own — reported by default, left out by `--events new` — so a script for new mail never runs on one. The Omarchy bar plugin toasts from those lines itself (app-name, glyph, click-to-focus and the replace-not-stack id all live in the plugin), and nothing desktop-shaped lives in `watch*.go`. @@ -800,7 +802,7 @@ themselves (`internal/cmd/watch_calendar.go`). Rings are coalesced per calendar `calendarCursor`) and each recording is a `recording_added`, `recording_updated` or `recording_deleted` line naming its calendar where a mail line names its box. The poll reports `calendar_added`, `calendar_updated` and `calendar_deleted`, and a recording feed's -409 is `calendar_resync` after skipping ahead to a fresh cursor from the list. The +409 is `calendar_resync` after skipping ahead to HEY's clock now, as a box does. The email-specific flags switch all of it off — `--box`, or an `--events` list naming only mail changes (`watchingCalendars` in watch_calendar.go) — and `ready` waits for the calendars' catch-up exactly as it waits for the boxes', on the same retry backoff and the diff --git a/docs/omarchy.md b/docs/omarchy.md index 4311d4b8..0c2c8fa7 100644 --- a/docs/omarchy.md +++ b/docs/omarchy.md @@ -215,8 +215,8 @@ and `--events new` selects the true ones. The rule: is new. `hey watch --box imbox --events new --exit-on-first` is "block until new mail", and a `--run-*` script sees `HEY_NEW=1` or `HEY_NEW=0`. - **A skip-ahead sets a floor.** A box that answered 409 was never read across the gap, so - the cursor it skips to — the box's last posting activity — becomes that box's floor: - activity at or before it is never new there, on a thread the watch knows or one it does + the cursor it skips to — HEY's clock at the skip, read the way the start is — becomes that + box's floor: activity at or before it is never new there, on a thread the watch knows or one it does not, so a reply the watch missed and then a move while still unseen is not new mail. Mail after the floor is. The floor is the box's own; a gap thread moved to another box is measured there and may read as new once — the `resync` line is the cue to re-read. diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index c4c3196f..215654b5 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -664,13 +664,13 @@ func (w *postingsWatch) readBox(ctx context.Context, box *watchedBox) error { if changes.FullSyncRequired { fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipping ahead, read the box with `hey box view %s`\n", box.name, box.kind) - skipped, err := w.skipAhead(ctx, box) + skippedTo, skipped, err := w.skipAhead(ctx, box) if err != nil { return err } // A resync says the box is worth re-reading; a box that is gone is not. if skipped { - w.report(ctx, watchEvent{Change: watchResync, At: watchTime(time.Now())}, box, nil) + w.report(ctx, watchEvent{Change: watchResync, At: watchTime(skippedTo)}, box, nil) } return nil } @@ -754,38 +754,61 @@ func (w *postingsWatch) settleBackoff() { } } -// skipAhead moves a box's cursor to the server's current one, which is the only way -// back once a box has changed more than an increment can carry, and says whether it -// did. +// skipAhead moves a box's cursor to HEY's clock now, which is the only way back once +// a box has changed more than an increment can carry, and says where it skipped to and +// whether it did. +// +// Not to the since in the box's posting_changes_url, which is what it used to take: +// that is the box's last posting activity rather than HEY's clock, a deletion or a +// bundled posting can come later than it, and the box list reaches the watch through +// the SDK's ETag cache, whose ETag — the box rows — posting activity never changes. A +// 304 after a long drop would hand back the since the watch had already fallen behind +// from, and every read after it would answer 409 again. The list is still read, for +// the feed's version and to learn whether the box is still there. // // A box the server no longer lists, or no longer serves a changes feed for, has no // cursor to skip to: keeping the one it had would answer 409 on every read, and // installing an empty one would be a usage error on every read instead. Either way the // box can't be followed any more, so it stops being watched — and nothing was skipped. -func (w *postingsWatch) skipAhead(ctx context.Context, box *watchedBox) (bool, error) { +// A clock that cannot be read leaves the cursor where it was, to be tried again on the +// retry's backoff like any read that failed. +func (w *postingsWatch) skipAhead(ctx context.Context, box *watchedBox) (time.Time, bool, error) { listed, err := sdk.Boxes().List(ctx) if err != nil { - return false, apierr.FromSDK(err) + return time.Time{}, false, apierr.FromSDK(err) } if listed == nil { - return false, apierr.ErrAPI(0, "could not list boxes") + return time.Time{}, false, apierr.ErrAPI(0, "could not list boxes") } for _, listedBox := range *listed { - if listedBox.Id == box.id { - cursor, err := watchCursor(listedBox.PostingChangesUrl, "") - if err != nil { - return false, err - } - if cursor.Since != "" { - box.cursor = cursor - w.newMail.skippedTo(box.id, cursor) - return true, nil + if listedBox.Id != box.id { + continue + } + cursor, err := watchCursor(listedBox.PostingChangesUrl, "") + if err != nil { + return time.Time{}, false, err + } + if cursor.Since == "" { + break + } + + now, err := serverNow(ctx) + if err != nil { + if permanentReadError(err) { + return time.Time{}, false, err } + fmt.Fprintf(w.errOut, "warning: could not skip %s ahead: %v\n", box.name, err) + w.readAgainLater(box) + return time.Time{}, false, nil } + cursor.Since = watchStartSince(now) + box.cursor = cursor + w.newMail.skippedTo(box.id, cursor) + return now, true, nil } - return false, w.stopWatching(box) + return time.Time{}, false, w.stopWatching(box) } // stopWatching drops a box the watch can't follow any longer. When it was the last one diff --git a/internal/cmd/watch_calendar.go b/internal/cmd/watch_calendar.go index 9af9a917..4a5af082 100644 --- a/internal/cmd/watch_calendar.go +++ b/internal/cmd/watch_calendar.go @@ -327,12 +327,12 @@ func (w *postingsWatch) readCalendar(ctx context.Context, calendar *watchedCalen if changes.FullSyncRequired { fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipping ahead, re-read the calendar\n", calendar.name) - skipped, err := w.skipCalendarAhead(ctx, calendar) + skippedTo, skipped, err := w.skipCalendarAhead(ctx, calendar) if err != nil { return err } if skipped { - w.reportCalendar(ctx, watchEvent{Change: watchCalendarResync, At: watchTime(time.Now())}, calendar.id, calendar.name) + w.reportCalendar(ctx, watchEvent{Change: watchCalendarResync, At: watchTime(skippedTo)}, calendar.id, calendar.name) } return nil } @@ -371,32 +371,49 @@ func (w *postingsWatch) reportRecordings(ctx context.Context, calendar *watchedC } } -// skipCalendarAhead moves a calendar's cursor to the server's current one, which is the -// only way back once its feed has fallen too far behind, and says whether it did. A -// calendar the server no longer lists cannot be followed any more and stops being watched -// — the calendar-level feed reports its deletion in its own time. -func (w *postingsWatch) skipCalendarAhead(ctx context.Context, calendar *watchedCalendar) (bool, error) { +// skipCalendarAhead moves a calendar's cursor to HEY's clock now, which is the only way +// back once its feed has fallen too far behind, and says where it skipped to and whether +// it did — the rule skipAhead follows for a box, and for the same reason: the since in +// the calendar's URL is its updated_at, not HEY's clock. The list is read for the feed's +// version and to learn whether the calendar is still there. A calendar the server no +// longer lists cannot be followed any more and stops being watched — the calendar-level +// feed reports its deletion in its own time. A clock that cannot be read leaves the +// cursor where it was, to be tried again on the retry's backoff. +func (w *postingsWatch) skipCalendarAhead(ctx context.Context, calendar *watchedCalendar) (time.Time, bool, error) { list, err := sdk.Calendars().ListWithChanges(ctx) if err != nil { - return false, apierr.FromSDK(err) + return time.Time{}, false, apierr.FromSDK(err) } if list == nil { - return false, apierr.ErrAPI(0, "could not list calendars") + return time.Time{}, false, apierr.ErrAPI(0, "could not list calendars") } for _, listed := range list.Calendars { - if listed.Calendar.Id == calendar.id { - cursor, err := hey.CalendarChangesCursorFrom(listed.RecordingChangesURL) - if err != nil { - return false, apierr.FromSDK(err) + if listed.Calendar.Id != calendar.id { + continue + } + cursor, err := hey.CalendarChangesCursorFrom(listed.RecordingChangesURL) + if err != nil { + return time.Time{}, false, apierr.FromSDK(err) + } + + now, err := serverNow(ctx) + if err != nil { + if permanentReadError(err) { + return time.Time{}, false, err } - calendar.cursor = cursor - return true, nil + fmt.Fprintf(w.errOut, "warning: could not skip %s ahead: %v\n", calendar.name, err) + w.calendar.unread[calendar.id] = true + w.armRetry() + return time.Time{}, false, nil } + cursor.Since = watchStartSince(now) + calendar.cursor = cursor + return now, true, nil } w.stopWatchingCalendar(calendar.id) - return false, nil + return time.Time{}, false, nil } // pollCalendarList reads the calendar-level feed: calendars that arrived are followed diff --git a/internal/cmd/watch_calendar_test.go b/internal/cmd/watch_calendar_test.go index a246af07..f4ce4685 100644 --- a/internal/cmd/watch_calendar_test.go +++ b/internal/cmd/watch_calendar_test.go @@ -264,6 +264,11 @@ func TestWatchCalendarSkipsAheadOnAFullSync(t *testing.T) { }`)) return } + if r.URL.Path == "/identity.json" { + w.Header().Set("Date", skipDate) + _, _ = w.Write([]byte(`{"id":1}`)) + return + } w.WriteHeader(http.StatusConflict) })) defer server.Close() @@ -283,8 +288,13 @@ func TestWatchCalendarSkipsAheadOnAFullSync(t *testing.T) { if event.Change != watchCalendarResync || event.Calendar == nil || event.Calendar.ID != 512 { t.Errorf("event = %+v, want a calendar_resync naming the calendar", event) } - if watch.calendar.calendars[512].cursor.Since != "2026-08-18T11:00:00.000Z" { - t.Errorf("cursor = %+v, want the server's own fresh cursor", watch.calendar.calendars[512].cursor) + skippedTo, err := time.Parse(time.RFC3339Nano, event.At) + if err != nil { + t.Fatalf("resync at %q: %v", event.At, err) + } + wantSkippedToHEYsClock(t, skippedTo) + if got := watch.calendar.calendars[512].cursor; got.Since != watchStartSince(skippedTo) || got.Version != "1" { + t.Errorf("cursor = %+v, want HEY's clock at the skip the resync names, and the feed's version", got) } } @@ -297,6 +307,11 @@ func TestWatchCalendarStopsWatchingAGoneCalendar(t *testing.T) { _, _ = w.Write([]byte(`{"calendars": [], "calendar_changes_url": "/calendar/changes.json?since=2026-08-18T11%3A00%3A00.000Z"}`)) return } + if r.URL.Path == "/identity.json" { + w.Header().Set("Date", skipDate) + _, _ = w.Write([]byte(`{"id":1}`)) + return + } w.WriteHeader(http.StatusConflict) })) defer server.Close() diff --git a/internal/cmd/watch_new.go b/internal/cmd/watch_new.go index fcf76eac..e49fb188 100644 --- a/internal/cmd/watch_new.go +++ b/internal/cmd/watch_new.go @@ -44,7 +44,7 @@ func trackNewMail(started time.Time) *newMail { // one it does not, updated later while still unseen — moved, say — would // otherwise measure its gap activity against an older record and read as // new. Activity at or before the floor is never new in that box; the cursor is -// the box's last posting activity, which bounds every thread in it. The floor +// HEY's clock at the skip, which bounds every thread in it. The floor // is the box's alone — a gap thread that moves to another box is measured // there, and may still read as new once. The resync line is the reader's cue // to re-read the box either way. HEY writes the cursor to the microsecond, so @@ -56,10 +56,11 @@ func (n *newMail) skippedTo(boxID int64, cursor hey.PostingChangesCursor) { } } -// serverNow is HEY's clock at the moment the watch began, read off the Date -// header of one cheap request, so that the cutoff between backlog and new mail -// sits on the same clock as every posting's active_at and a workstation running -// fast or slow can neither call the backlog new nor sit on new mail. +// serverNow is HEY's clock at the moment it is asked — the watch's start, or a +// skip-ahead's — read off the Date header of one cheap request, so that the +// cutoff between backlog and new mail sits on the same clock as every posting's +// active_at and a workstation running fast or slow can neither call the backlog +// new nor sit on new mail. // // Date is the server's clock when it answered, and the watch began when it // asked: mail that lands in between is later than the start but no later than diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index 1f80a0a0..74c808ac 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -422,13 +422,18 @@ func TestWatchStopsOnAReadThatCannotWork(t *testing.T) { } } -// boxesAndChanges answers the two reads a skip-ahead makes: a changes feed that is too far -// behind to follow, and the box list it then looks for a fresh cursor in. +// boxesAndChanges answers the reads a skip-ahead makes: a changes feed that is too far +// behind to follow, the box list it looks for the box and its feed's version in, and +// HEY's clock, which it skips to. func boxesAndChanges(t *testing.T, boxes string) *httptest.Server { t.Helper() return httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { switch r.URL.Path { + case "/identity.json": + w.Header().Set("Date", skipDate) + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{"id":1}`)) case "/boxes.json": w.Header().Set("Content-Type", "application/json") _, _ = w.Write([]byte(boxes)) @@ -438,9 +443,22 @@ func boxesAndChanges(t *testing.T, boxes string) *httptest.Server { })) } -func TestWatchSkipsAheadToTheBoxesOwnCursor(t *testing.T) { +// HEY's clock when a skip-ahead reads it. +const skipDate = "Fri, 21 Aug 2026 11:05:00 GMT" + +// wantSkippedToHEYsClock checks a skip-ahead's point: HEY's clock at the skip, read the +// way the start is — a whole millisecond, just before the Date header. +func wantSkippedToHEYsClock(t *testing.T, skippedTo time.Time) { + t.Helper() + date := time.Date(2026, 8, 21, 11, 5, 0, 0, time.UTC) + if !skippedTo.Before(date) || date.Sub(skippedTo) > time.Second { + t.Errorf("skipped to %v, want HEY's clock at the skip, just before %v", skippedTo, date) + } +} + +func TestWatchSkipsAheadToHEYsClock(t *testing.T) { t.Setenv("HEY_TOKEN", "test-token") - server := boxesAndChanges(t, `[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"/boxes/24088/postings/changes.json?since=2026-08-21T11%3A02%3A00.000Z&v=2"}]`) + server := boxesAndChanges(t, `[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"/boxes/24088/postings/changes.json?since=2026-08-21T11%3A02%3A00.518496Z&v=2"}]`) defer server.Close() initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) @@ -455,11 +473,91 @@ func TestWatchSkipsAheadToTheBoxesOwnCursor(t *testing.T) { if watch.boxes[24088] == nil { t.Fatal("the box should still be watched") } - if got := watch.boxes[24088].cursor.Since; got != "2026-08-21T11:02:00.000Z" { - t.Errorf("cursor = %q, want the server's current one", got) + floor := watch.newMail.floors[24088] + wantSkippedToHEYsClock(t, floor) + if got := watch.boxes[24088].cursor; got.Since != watchStartSince(floor) || got.Version != "2" { + t.Errorf("cursor = %+v, want HEY's clock at the skip, the new-mail floor, and the box's feed version", got) + } +} + +// A box list the SDK revalidates answers 304 while no box row has changed, which is +// every posting's activity — so after a long drop the list hands back the since the +// watch fell behind from. Skipping to it answered 409 again on every read; skipping to +// HEY's clock gets past it. +func TestWatchSkipAheadGetsPastACachedBoxList(t *testing.T) { + t.Setenv("HEY_TOKEN", "test-token") + t.Setenv("XDG_CACHE_HOME", t.TempDir()) + + behind := time.Date(2026, 8, 21, 11, 0, 0, 0, time.UTC) // a since before this is too far behind + var mu sync.Mutex + var notModified, conflicts int + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + mu.Lock() + defer mu.Unlock() + switch r.URL.Path { + case "/identity.json": + w.Header().Set("Date", skipDate) + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{"id":1}`)) + case "/boxes.json": + w.Header().Set("ETag", `W/"boxes-unchanged"`) + if r.Header.Get("If-None-Match") == `W/"boxes-unchanged"` { + notModified++ + w.WriteHeader(http.StatusNotModified) + return + } + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"/boxes/24088/postings/changes.json?since=2026-08-01T09%3A00%3A00.000000Z&v=2"}]`)) + default: + since, _ := time.Parse(time.RFC3339Nano, r.URL.Query().Get("since")) + if since.Before(behind) { + // As HEY answers: `head :conflict`, no body. + conflicts++ + w.WriteHeader(http.StatusConflict) + return + } + w.Header().Set("Content-Type", "application/json") + w.Header().Set("Link", `<`+r.URL.Path+`?since=2026-08-21T11%3A06%3A12.250000Z&v=2>; rel="next"`) + _, _ = w.Write([]byte(`{"added":[{"id":9004,"kind":"topic","box_id":24088,"name":"Re: Lunch on Thursday?","active_at":"2026-08-21T11:06:12.250Z","created_at":"2026-08-21T11:06:12.250Z","creator":{"name":"Maria Delgado"}}]}`)) + } + })) + defer server.Close() + initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) + + // The box list as the watch read it at its start, now in the SDK's cache. + if _, err := sdk.Boxes().List(context.Background()); err != nil { + t.Fatalf("unexpected error: %v", err) + } + + watch, out := newTestWatch("added", "resync") + cursor, err := watchCursor(server.URL+"/boxes/24088/postings/changes.json?since=2026-08-01T09%3A00%3A00.000000Z&v=2", "") + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + watch.boxes[24088].cursor = cursor + + ringBox(t, watch) + ringBox(t, watch) + + mu.Lock() + defer mu.Unlock() + if notModified == 0 { + t.Fatal("the skip-ahead should have read the box list from the cache, as HEY answers a list whose rows have not changed") + } + if conflicts != 1 { + t.Errorf("the feed answered 409 %d times, want once — the skip-ahead should get past it", conflicts) } - if got := watch.newMail.floors[24088]; !got.Equal(time.Date(2026, 8, 21, 11, 2, 0, 0, time.UTC)) { - t.Errorf("new-mail floor = %v, want the box's floor at the cursor it skipped to", got) + lines := watchLines(t, out) + if len(lines) != 2 || lines[0]["change"] != watchResync || lines[1]["change"] != "added" || lines[1]["posting_id"] != float64(9004) { + t.Fatalf("wrote %v, want one resync and then the change after it", lines) + } + skippedTo, err := time.Parse(time.RFC3339Nano, lines[0]["at"].(string)) + if err != nil { + t.Fatalf("resync at %v: %v", lines[0]["at"], err) + } + wantSkippedToHEYsClock(t, skippedTo) + if floor := watch.newMail.floors[24088]; watchTime(floor) != lines[0]["at"] { + t.Errorf("new-mail floor = %v, want the skip point the resync names", floor) } } @@ -1202,10 +1300,11 @@ func TestWatchReportsAResyncAfterSkippingAhead(t *testing.T) { var server *httptest.Server server = httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { if strings.Contains(r.URL.Path, "/postings/changes") { - // As haystack answers: `head :conflict`, no body. + // As HEY answers: `head :conflict`, no body. w.WriteHeader(http.StatusConflict) return } + w.Header().Set("Date", skipDate) w.Header().Set("Content-Type", "application/json") _, _ = w.Write([]byte(`[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"` + server.URL + `/boxes/24088/postings/changes.json?since=2026-08-21T12%3A00%3A00.000Z&v=2"}]`)) })) @@ -1230,8 +1329,13 @@ func TestWatchReportsAResyncAfterSkippingAhead(t *testing.T) { if event.Change != watchResync || event.Box == nil || event.Box.ID != 24088 { t.Errorf("event = %+v, want a resync for the Imbox", event) } - if watch.boxes[24088].cursor.Since != "2026-08-21T12:00:00.000Z" { - t.Errorf("cursor = %+v, want it moved to the server's current one", watch.boxes[24088].cursor) + skippedTo, err := time.Parse(time.RFC3339Nano, event.At) + if err != nil { + t.Fatalf("resync at %q: %v", event.At, err) + } + wantSkippedToHEYsClock(t, skippedTo) + if watch.boxes[24088].cursor.Since != watchStartSince(skippedTo) { + t.Errorf("cursor = %+v, want it moved to HEY's clock at the skip the resync names", watch.boxes[24088].cursor) } } From 6c7b60ab7a2d9b594790353e5baac5697e133cfc Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 15:35:59 -0400 Subject: [PATCH 08/17] Count the clock request's time in the documented replay window The start is the Date header taken back by the whole of the clock request, retries included, so a change can be reported from a second before the watch began plus however long that request took, not about a second. The help text, docs/cli.md, docs/omarchy.md, the skill and AGENTS.md now say so. --- AGENTS.md | 2 +- docs/cli.md | 5 +++-- docs/omarchy.md | 3 ++- internal/cmd/watch.go | 5 +++-- skills/hey/SKILL.md | 3 ++- 5 files changed, 11 insertions(+), 7 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 16668f6c..e35e9f03 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -692,7 +692,7 @@ cutoff every feed and new mail are measured against, since a fast one would skip a slow one would report history. That is HEY's semantics and state across events, so the CLI decides it once; what to do about it is the reader's. The Date header is whole seconds, so the start can be up to a second -(plus the request's time) early and a change from that window is reported; nothing HEY +(plus the clock request's whole time, retries included) early and a change from that window is reported; nothing HEY serves says the time finer — Action Cable pings are whole seconds too — and rounding the other way would skip changes. A 409 skip-ahead moves the cursor to HEY's clock now (`serverNow`, not the box list's since, which the ETag cache can serve unchanged and would diff --git a/docs/cli.md b/docs/cli.md index 19914b72..b10ace00 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -340,8 +340,9 @@ Runs until interrupted, printing changes as they happen, one line each. What cha the watch began is not reported unless `--since` reads back to it first, so `--exit-on-first` waits for a change rather than stopping on an old one. When the watch began is read off HEY's clock, and a watch that cannot read it exits with an error rather than -guess. That clock is read to the whole second, so a change from up to about a second before -the watch began can still be reported (and be new, and end `--exit-on-first`); its `at` says +guess. That clock is read to the whole second and taken back by however long the request +took (retries included), so a change from up to a second before the watch began, plus that +request's time, can still be reported (and be new, and end `--exit-on-first`); its `at` says when it happened. Rounding the other way would skip changes that came after: ```json diff --git a/docs/omarchy.md b/docs/omarchy.md index 0c2c8fa7..f4bbbdd6 100644 --- a/docs/omarchy.md +++ b/docs/omarchy.md @@ -194,7 +194,8 @@ and `--events new` selects the true ones. The rule: so a workstation running fast or slow neither calls the backlog new nor sits on new mail (a watch that cannot read HEY's clock exits with an error rather than use its own); whole seconds, rounded down, so the doubt falls on the side of calling mail a moment old - new — mail from up to about a second before the watch began can read as new — and every + new — mail from up to a second before the watch began, plus however long the clock request + took (retries included), can read as new — and every box's cursor starts at that start, so mail that lands while the watch is starting up is read and is new. `active_at` moves on new mail only, not on a seen flip, a mute or a move, so reading a thread, marking it unseen again or moving it diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index 215654b5..92e79ae3 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -75,8 +75,9 @@ func newWatchCommand() *watchCommand { Long: `Print email threads and calendar changes as they happen: piped or with --json, one JSON object per line; at a terminal, one text line each. Runs until interrupted. What changed before the watch began is not reported, unless --since reads back to it first — -save a change from up to about a second before, since HEY's clock is read to the whole -second; its "at" says when it happened. +save a change from just before it: HEY's clock is read to the whole second, and taken back +by however long reading it took, so a change up to a second before the watch asked, plus +that request's time, may be reported. Its "at" says when it happened. Changes can drive a command instead of being printed, and that is a choice between two behaviours: --run-async spawns the command per change and moves on, so a slow one never diff --git a/skills/hey/SKILL.md b/skills/hey/SKILL.md index 03adad1e..c950f52a 100644 --- a/skills/hey/SKILL.md +++ b/skills/hey/SKILL.md @@ -717,7 +717,8 @@ the posting is new mail — unseen, not muted, and active since the watch last s or since the watch began for a thread it has not seen; the backlog `--since` reads is never new, nor is reading, muting or moving a thread, and a reply on a known thread is. Without `--since`, nothing from before the watch began is reported, save a change from up to -about a second before (HEY's clock is read to the whole second); its `at` says when it happened. +a second before it plus however long reading HEY's clock took (that clock is read to the whole +second, and taken back by the request's time); its `at` says when it happened. `--events new` selects the new ones, alone or in a union with the other three. A deleted posting carries no `posting`, `thread_id` or `new`. Three more lines describe the watch itself: `{"change": "ready"}` once every box and calendar is caught up and the subscription From 7291916af7445dfd7b21daa3b2dded83fde01f2c Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 15:37:37 -0400 Subject: [PATCH 09/17] End a skip-ahead quietly when the watch is interrupted An interrupt or --timeout while a skip-ahead read HEY's clock fell through to the retry path: it warned that the box or calendar could not be skipped ahead and armed a retry the ending watch would never run. Both skip-aheads now check the context first, as the feed reads beside them do, and return quietly with the cursor where it was. --- internal/cmd/watch.go | 12 ++++--- internal/cmd/watch_calendar.go | 14 +++++--- internal/cmd/watch_test.go | 66 ++++++++++++++++++++++++++++++++++ 3 files changed, 83 insertions(+), 9 deletions(-) diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index 92e79ae3..9fad89a4 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -796,12 +796,16 @@ func (w *postingsWatch) skipAhead(ctx context.Context, box *watchedBox) (time.Ti now, err := serverNow(ctx) if err != nil { - if permanentReadError(err) { + switch { + case ctx.Err() != nil: + return time.Time{}, false, nil //nolint:nilerr // an interrupt or a --timeout is how a watch is meant to end + case permanentReadError(err): return time.Time{}, false, err + default: + fmt.Fprintf(w.errOut, "warning: could not skip %s ahead: %v\n", box.name, err) + w.readAgainLater(box) + return time.Time{}, false, nil } - fmt.Fprintf(w.errOut, "warning: could not skip %s ahead: %v\n", box.name, err) - w.readAgainLater(box) - return time.Time{}, false, nil } cursor.Since = watchStartSince(now) box.cursor = cursor diff --git a/internal/cmd/watch_calendar.go b/internal/cmd/watch_calendar.go index 4a5af082..cb595d65 100644 --- a/internal/cmd/watch_calendar.go +++ b/internal/cmd/watch_calendar.go @@ -399,13 +399,17 @@ func (w *postingsWatch) skipCalendarAhead(ctx context.Context, calendar *watched now, err := serverNow(ctx) if err != nil { - if permanentReadError(err) { + switch { + case ctx.Err() != nil: + return time.Time{}, false, nil //nolint:nilerr // an interrupt or a --timeout is how a watch is meant to end + case permanentReadError(err): return time.Time{}, false, err + default: + fmt.Fprintf(w.errOut, "warning: could not skip %s ahead: %v\n", calendar.name, err) + w.calendar.unread[calendar.id] = true + w.armRetry() + return time.Time{}, false, nil } - fmt.Fprintf(w.errOut, "warning: could not skip %s ahead: %v\n", calendar.name, err) - w.calendar.unread[calendar.id] = true - w.armRetry() - return time.Time{}, false, nil } cursor.Since = watchStartSince(now) calendar.cursor = cursor diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index 74c808ac..aae1eb9c 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -480,6 +480,72 @@ func TestWatchSkipsAheadToHEYsClock(t *testing.T) { } } +// cancelledAtTheClock is HEY as a skip-ahead meets it when the watch is interrupted +// while it reads the clock: the feed is too far behind, the box and calendar lists +// answer, and the clock request is where the interrupt lands. +func cancelledAtTheClock(t *testing.T, cancel context.CancelFunc) { + t.Helper() + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + switch r.URL.Path { + case "/identity.json": + cancel() + <-r.Context().Done() + case "/boxes.json": + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"/boxes/24088/postings/changes.json?since=2026-08-21T11%3A02%3A00.518496Z&v=2"}]`)) + case "/calendars.json": + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{"calendars": [{"calendar": {"id": 512, "name": "Household"}, + "recording_changes_url": "/calendars/512/recording/changes.json?since=2026-08-18T11%3A00%3A00.000000Z&v=1"}]}`)) + default: + w.WriteHeader(http.StatusConflict) + } + })) + t.Cleanup(server.Close) + t.Setenv("HEY_TOKEN", "test-token") + initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) +} + +// An interrupt or --timeout while a skip-ahead reads HEY's clock is how a watch is +// meant to end, not a failed read: nothing is warned about and no retry is armed. +func TestWatchSkipAheadEndsQuietlyWhenInterrupted(t *testing.T) { + for _, feed := range []string{"box", "calendar"} { + t.Run(feed, func(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + cancelledAtTheClock(t, cancel) + + watch, out := newTestWatch("added", "resync", "calendar_resync") + errOut := &bytes.Buffer{} + watch.errOut = errOut + watch.boxes[24088].cursor.Since = "2026-08-01T00:00:00.000Z" + watch.calendar = newTestCalendarsWatch(t, &watchedCalendar{id: 512, name: "Household", cursor: hey.CalendarChangesCursor{Since: "2026-08-01T00:00:00.000Z", Version: "1"}}) + + var err error + if feed == "box" { + err = watch.readBox(ctx, watch.boxes[24088]) + } else { + err = watch.readCalendar(ctx, watch.calendar.calendars[512]) + } + if err != nil { + t.Fatalf("read = %v, want an interrupted skip-ahead to end quietly", err) + } + if strings.Contains(errOut.String(), "warning") { + t.Errorf("stderr = %q, want no warning for an interrupt", errOut.String()) + } + if watch.retry != nil || len(watch.unread) != 0 || len(watch.calendar.unread) != 0 { + t.Error("an interrupted skip-ahead should not arm a retry") + } + if out.Len() != 0 { + t.Errorf("wrote %q, want no resync for a skip that did not happen", out.String()) + } + if watch.boxes[24088].cursor.Since != "2026-08-01T00:00:00.000Z" || watch.calendar.calendars[512].cursor.Since != "2026-08-01T00:00:00.000Z" { + t.Error("an interrupted skip-ahead should leave the cursor where it was") + } + }) + } +} + // A box list the SDK revalidates answers 304 while no box row has changed, which is // every posting's activity — so after a long drop the list hands back the since the // watch fell behind from. Skipping to it answered 409 again on every read; skipping to From b0967a1cb36fc8571c9eed4007456f48ba9b5487 Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 15:48:20 -0400 Subject: [PATCH 10/17] Say what replaces the since watchCursor reads watchCursor's comment still said a skip-ahead resumes from HEY's since. Neither caller keeps it without --since: a first read starts at the watch's start and a skip-ahead at HEY's clock, both keeping the feed version. --- internal/cmd/watch.go | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index 9fad89a4..3ebe08eb 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -313,9 +313,10 @@ func boxIs(box generated.Box, wanted string) bool { wanted == strconv.FormatInt(box.Id, 10) } -// watchCursor reads the cursor out of a box's changes URL — HEY's own, which a skip-ahead -// resumes from — unless --since moves it. Without --since, a watch's first read starts -// at the watch's start instead (watchStartSince). +// watchCursor reads the cursor out of a box's changes URL, moved by --since. Its since +// is HEY's, which neither caller keeps without --since: a watch's first read replaces it +// with the watch's start (watchStartSince), and a skip-ahead with HEY's clock at the +// skip. Both keep the feed version it names. func watchCursor(changesURL, since string) (hey.PostingChangesCursor, error) { if changesURL == "" { return hey.PostingChangesCursor{}, nil From 8c29454185ac0fdb93ca518a66d485e0dabfab3c Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 15:58:37 -0400 Subject: [PATCH 11/17] Skip ahead to when HEY's clock answered, not when it was asked A skip-ahead took its point from serverNow, the watch start's reading: the Date header taken back by the whole request, retries included. The start needs that, to catch what lands while it is asked. A skip has already given up the gap, which the resync line says, so it has nothing to catch there, and a point taken back by a slow or retried request could leave a busy feed still too far behind to follow. Skip-aheads now read serverNowAnswered: the millisecond before the Date header. --- AGENTS.md | 9 +++---- docs/omarchy.md | 2 +- internal/cmd/watch.go | 8 +++---- internal/cmd/watch_calendar.go | 4 ++-- internal/cmd/watch_new.go | 44 ++++++++++++++++++++++++++-------- internal/cmd/watch_test.go | 10 ++++---- 6 files changed, 51 insertions(+), 26 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index e35e9f03..7293b839 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -694,9 +694,10 @@ is HEY's semantics and state across events, so the CLI decides it once; what to it is the reader's. The Date header is whole seconds, so the start can be up to a second (plus the clock request's whole time, retries included) early and a change from that window is reported; nothing HEY serves says the time finer — Action Cable pings are whole seconds too — and rounding the -other way would skip changes. A 409 skip-ahead moves the cursor to HEY's clock now -(`serverNow`, not the box list's since, which the ETag cache can serve unchanged and would -409 again) and sets that box's floor there (`newMail.skippedTo`): activity at or before it +other way would skip changes. A 409 skip-ahead moves the cursor to HEY's clock when it +answered (`serverNowAnswered` — not taken back by the request's time, since a resync has +no gap to catch and a slow request could leave a busy feed still behind; and not the box +list's since, which the ETag cache can serve unchanged and would 409 again) and sets that box's floor there (`newMail.skippedTo`): activity at or before it is never new there, known thread or not, because the watch never read the gap. A calendar's 409 skips the same way. `resync` is an event of its own — reported by default, left out by `--events new` — so a script for new mail never runs on one. The Omarchy bar plugin toasts from those lines itself (app-name, glyph, @@ -802,7 +803,7 @@ themselves (`internal/cmd/watch_calendar.go`). Rings are coalesced per calendar `calendarCursor`) and each recording is a `recording_added`, `recording_updated` or `recording_deleted` line naming its calendar where a mail line names its box. The poll reports `calendar_added`, `calendar_updated` and `calendar_deleted`, and a recording feed's -409 is `calendar_resync` after skipping ahead to HEY's clock now, as a box does. The +409 is `calendar_resync` after skipping ahead to HEY's clock, as a box does. The email-specific flags switch all of it off — `--box`, or an `--events` list naming only mail changes (`watchingCalendars` in watch_calendar.go) — and `ready` waits for the calendars' catch-up exactly as it waits for the boxes', on the same retry backoff and the diff --git a/docs/omarchy.md b/docs/omarchy.md index f4bbbdd6..4157449c 100644 --- a/docs/omarchy.md +++ b/docs/omarchy.md @@ -216,7 +216,7 @@ and `--events new` selects the true ones. The rule: is new. `hey watch --box imbox --events new --exit-on-first` is "block until new mail", and a `--run-*` script sees `HEY_NEW=1` or `HEY_NEW=0`. - **A skip-ahead sets a floor.** A box that answered 409 was never read across the gap, so - the cursor it skips to — HEY's clock at the skip, read the way the start is — becomes that + the cursor it skips to — HEY's clock when the skip read it — becomes that box's floor: activity at or before it is never new there, on a thread the watch knows or one it does not, so a reply the watch missed and then a move while still unseen is not new mail. Mail after the floor is. The floor is the box's own; a gap thread moved to another box is diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index 3ebe08eb..79397c90 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -756,9 +756,9 @@ func (w *postingsWatch) settleBackoff() { } } -// skipAhead moves a box's cursor to HEY's clock now, which is the only way back once -// a box has changed more than an increment can carry, and says where it skipped to and -// whether it did. +// skipAhead moves a box's cursor to HEY's clock when it answered (serverNowAnswered), +// which is the only way back once a box has changed more than an increment can carry, +// and says where it skipped to and whether it did. // // Not to the since in the box's posting_changes_url, which is what it used to take: // that is the box's last posting activity rather than HEY's clock, a deletion or a @@ -795,7 +795,7 @@ func (w *postingsWatch) skipAhead(ctx context.Context, box *watchedBox) (time.Ti break } - now, err := serverNow(ctx) + now, err := serverNowAnswered(ctx) if err != nil { switch { case ctx.Err() != nil: diff --git a/internal/cmd/watch_calendar.go b/internal/cmd/watch_calendar.go index cb595d65..d3108779 100644 --- a/internal/cmd/watch_calendar.go +++ b/internal/cmd/watch_calendar.go @@ -371,7 +371,7 @@ func (w *postingsWatch) reportRecordings(ctx context.Context, calendar *watchedC } } -// skipCalendarAhead moves a calendar's cursor to HEY's clock now, which is the only way +// skipCalendarAhead moves a calendar's cursor to HEY's clock when it answered, the only way // back once its feed has fallen too far behind, and says where it skipped to and whether // it did — the rule skipAhead follows for a box, and for the same reason: the since in // the calendar's URL is its updated_at, not HEY's clock. The list is read for the feed's @@ -397,7 +397,7 @@ func (w *postingsWatch) skipCalendarAhead(ctx context.Context, calendar *watched return time.Time{}, false, apierr.FromSDK(err) } - now, err := serverNow(ctx) + now, err := serverNowAnswered(ctx) if err != nil { switch { case ctx.Err() != nil: diff --git a/internal/cmd/watch_new.go b/internal/cmd/watch_new.go index e49fb188..57766094 100644 --- a/internal/cmd/watch_new.go +++ b/internal/cmd/watch_new.go @@ -56,11 +56,10 @@ func (n *newMail) skippedTo(boxID int64, cursor hey.PostingChangesCursor) { } } -// serverNow is HEY's clock at the moment it is asked — the watch's start, or a -// skip-ahead's — read off the Date header of one cheap request, so that the -// cutoff between backlog and new mail sits on the same clock as every posting's -// active_at and a workstation running fast or slow can neither call the backlog -// new nor sit on new mail. +// serverNow is HEY's clock at the moment the watch began, read off the Date +// header of one cheap request, so that the cutoff between backlog and new mail +// sits on the same clock as every posting's active_at and a workstation running +// fast or slow can neither call the backlog new nor sit on new mail. // // Date is the server's clock when it answered, and the watch began when it // asked: mail that lands in between is later than the start but no later than @@ -88,20 +87,45 @@ func (n *newMail) skippedTo(boxID int64, cursor hey.PostingChangesCursor) { // would report history. A request that fails here would fail at the box list // next anyway. func serverNow(ctx context.Context) (time.Time, error) { + answered, took, err := readHEYsClock(ctx) + if err != nil { + return time.Time{}, err + } + + return cutoffBefore(answered.Add(-took)), nil +} + +// serverNowAnswered is HEY's clock when it answered, not taken back by the +// request's time: where a skip-ahead resumes. A skip has already given up on +// the gap — the resync line says so — so there is nothing to catch between +// asking and the answer, and a skip point taken back by a slow or retried +// request could leave a busy feed still too far behind to follow. +func serverNowAnswered(ctx context.Context) (time.Time, error) { + answered, _, err := readHEYsClock(ctx) + if err != nil { + return time.Time{}, err + } + + return cutoffBefore(answered), nil +} + +// readHEYsClock asks HEY the time: the Date header of its answer, and how long +// the request took on the local monotonic clock. +func readHEYsClock(ctx context.Context) (time.Time, time.Duration, error) { started := time.Now() response, err := rootSDK.Get(ctx, "/identity.json?clock="+strconv.FormatInt(started.UnixNano(), 10)) if err != nil { - return time.Time{}, apierr.FromSDK(err) + return time.Time{}, 0, apierr.FromSDK(err) } if response == nil || response.FromCache { - return time.Time{}, apierr.ErrAPI(0, "could not read HEY's clock — the watch needs it to tell what happened after it began") + return time.Time{}, 0, apierr.ErrAPI(0, "could not read HEY's clock — the watch needs it to tell what happened after it began") } - at, err := http.ParseTime(response.Headers.Get("Date")) + answered, err := http.ParseTime(response.Headers.Get("Date")) if err != nil { - return time.Time{}, apierr.ErrAPI(0, "HEY's answer carried no Date header — the watch needs HEY's clock to tell what happened after it began") + return time.Time{}, 0, apierr.ErrAPI(0, "HEY's answer carried no Date header — the watch needs HEY's clock to tell what happened after it began") } - return cutoffBefore(at.Add(-time.Since(started))), nil + return answered, time.Since(started), nil } // watchStartSince is where a feed's first read begins without --since: the diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index aae1eb9c..55b9c5bd 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -446,13 +446,13 @@ func boxesAndChanges(t *testing.T, boxes string) *httptest.Server { // HEY's clock when a skip-ahead reads it. const skipDate = "Fri, 21 Aug 2026 11:05:00 GMT" -// wantSkippedToHEYsClock checks a skip-ahead's point: HEY's clock at the skip, read the -// way the start is — a whole millisecond, just before the Date header. +// wantSkippedToHEYsClock checks a skip-ahead's point: HEY's clock when it answered — the +// millisecond before the Date header, not taken back by the request's time, which a +// skip has no gap to catch in and which could leave a busy feed still behind. func wantSkippedToHEYsClock(t *testing.T, skippedTo time.Time) { t.Helper() - date := time.Date(2026, 8, 21, 11, 5, 0, 0, time.UTC) - if !skippedTo.Before(date) || date.Sub(skippedTo) > time.Second { - t.Errorf("skipped to %v, want HEY's clock at the skip, just before %v", skippedTo, date) + if want := time.Date(2026, 8, 21, 11, 4, 59, 999000000, time.UTC); !skippedTo.Equal(want) { + t.Errorf("skipped to %v, want HEY's clock when it answered, %v", skippedTo, want) } } From 3202f12324e2537856188a05baaab03316e2e11a Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 16:20:44 -0400 Subject: [PATCH 12/17] Read a skip-ahead's list past the SDK's cache MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A skip-ahead keeps the feed version from the box or calendar list and replaces only the since. The list comes through the SDK's ETag cache, and HEY's ETag for /boxes.json is the box rows — for /calendars.json the calendars and the selection — which a new feed version need not change. If HEY moved a feed to a new version, the 304 handed back the old one, HEY answers 409 for a version it no longer speaks (Changes::BaseController#version_mismatch?), and every read after every skip was another 409 and another resync. The SDK has no per-request way past its cache, so newUncachedSDKClient builds a sibling of the CLI's client from the same configuration and options, minus the cache, scoped to the same account. Skip-aheads read their list through it; a 409 is rare enough to build one each time. --- internal/cmd/sdk.go | 17 +++++++ internal/cmd/watch.go | 18 +++++--- internal/cmd/watch_calendar.go | 9 +++- internal/cmd/watch_calendar_test.go | 72 +++++++++++++++++++++++++++++ internal/cmd/watch_test.go | 31 ++++++++----- 5 files changed, 127 insertions(+), 20 deletions(-) diff --git a/internal/cmd/sdk.go b/internal/cmd/sdk.go index c064d2d4..8d3637c1 100644 --- a/internal/cmd/sdk.go +++ b/internal/cmd/sdk.go @@ -136,6 +136,23 @@ func newSDKClient(extra ...hey.ClientOption) *hey.Client { return hey.NewClient(sdkClientCfg, nil, opts...) } +// newUncachedSDKClient builds a sibling of sdk — same configuration, same account — +// without the response cache, for a read a 304 must not answer. The cache revalidates +// on HEY's ETag, and an ETag can cover less than the body: /boxes.json's is the box +// rows, so a box's posting_changes_url, feed version and all, can change under it. +// The SDK has no per-request way past its cache, so this is a client of its own. +func newUncachedSDKClient(ctx context.Context) (*hey.Client, error) { + uncached := *sdkClientCfg + uncached.CacheEnabled = false + uncached.CacheDir = "" + client := hey.NewClient(&uncached, nil, sdkClientOpts...) + + if accountID, scoped := sdk.AccountID(); scoped { + return client.ForAccount(ctx, accountID) + } + return client, nil +} + func selectConfiguredAccount(ctx context.Context) error { client, err := clientForAccountSelection(ctx, rootSDK, cfg.AccountID) if err != nil { diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index 79397c90..3ec2fcc6 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -761,12 +761,12 @@ func (w *postingsWatch) settleBackoff() { // and says where it skipped to and whether it did. // // Not to the since in the box's posting_changes_url, which is what it used to take: -// that is the box's last posting activity rather than HEY's clock, a deletion or a -// bundled posting can come later than it, and the box list reaches the watch through -// the SDK's ETag cache, whose ETag — the box rows — posting activity never changes. A -// 304 after a long drop would hand back the since the watch had already fallen behind -// from, and every read after it would answer 409 again. The list is still read, for -// the feed's version and to learn whether the box is still there. +// that is the box's last posting activity rather than HEY's clock, and a deletion or a +// bundled posting can come later than it. The list is still read, for the feed's +// version and to learn whether the box is still there — and read past the SDK's ETag +// cache (newUncachedSDKClient — a skip is rare enough to build one each time), because HEY's ETag for it is the box rows, which neither +// posting activity nor a new feed version touches. A 304 would hand back the version +// HEY had just refused, and a version HEY refuses answers 409 on every read. // // A box the server no longer lists, or no longer serves a changes feed for, has no // cursor to skip to: keeping the one it had would answer 409 on every read, and @@ -775,7 +775,11 @@ func (w *postingsWatch) settleBackoff() { // A clock that cannot be read leaves the cursor where it was, to be tried again on the // retry's backoff like any read that failed. func (w *postingsWatch) skipAhead(ctx context.Context, box *watchedBox) (time.Time, bool, error) { - listed, err := sdk.Boxes().List(ctx) + client, err := newUncachedSDKClient(ctx) + if err != nil { + return time.Time{}, false, apierr.FromSDK(err) + } + listed, err := client.Boxes().List(ctx) if err != nil { return time.Time{}, false, apierr.FromSDK(err) } diff --git a/internal/cmd/watch_calendar.go b/internal/cmd/watch_calendar.go index d3108779..0f8156c6 100644 --- a/internal/cmd/watch_calendar.go +++ b/internal/cmd/watch_calendar.go @@ -375,12 +375,17 @@ func (w *postingsWatch) reportRecordings(ctx context.Context, calendar *watchedC // back once its feed has fallen too far behind, and says where it skipped to and whether // it did — the rule skipAhead follows for a box, and for the same reason: the since in // the calendar's URL is its updated_at, not HEY's clock. The list is read for the feed's -// version and to learn whether the calendar is still there. A calendar the server no +// version and to learn whether the calendar is still there, past the SDK's cache as a +// box's is: a new feed version need not change the list's ETag. A calendar the server no // longer lists cannot be followed any more and stops being watched — the calendar-level // feed reports its deletion in its own time. A clock that cannot be read leaves the // cursor where it was, to be tried again on the retry's backoff. func (w *postingsWatch) skipCalendarAhead(ctx context.Context, calendar *watchedCalendar) (time.Time, bool, error) { - list, err := sdk.Calendars().ListWithChanges(ctx) + client, err := newUncachedSDKClient(ctx) + if err != nil { + return time.Time{}, false, apierr.FromSDK(err) + } + list, err := client.Calendars().ListWithChanges(ctx) if err != nil { return time.Time{}, false, apierr.FromSDK(err) } diff --git a/internal/cmd/watch_calendar_test.go b/internal/cmd/watch_calendar_test.go index f4ce4685..64354edf 100644 --- a/internal/cmd/watch_calendar_test.go +++ b/internal/cmd/watch_calendar_test.go @@ -298,6 +298,78 @@ func TestWatchCalendarSkipsAheadOnAFullSync(t *testing.T) { } } +// A calendar's feed can move to a new version without the calendar list's ETag — its +// calendars and the selection — changing, so the skip-ahead reads the list past the cache. +func TestWatchCalendarSkipAheadReadsTheListPastTheCache(t *testing.T) { + t.Setenv("HEY_TOKEN", "test-token") + t.Setenv("XDG_CACHE_HOME", t.TempDir()) + + var mu sync.Mutex + var notModified, conflicts int + version := "1" + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + mu.Lock() + defer mu.Unlock() + switch r.URL.Path { + case "/identity.json": + w.Header().Set("Date", skipDate) + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{"id":1}`)) + case "/calendars.json": + w.Header().Set("ETag", `W/"calendars-unchanged"`) + if r.Header.Get("If-None-Match") == `W/"calendars-unchanged"` { + notModified++ + w.WriteHeader(http.StatusNotModified) + return + } + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{"calendars": [{"calendar": {"id": 512, "name": "Household"}, + "recording_changes_url": "/calendars/512/recording/changes.json?since=2026-08-18T11%3A00%3A00.000000Z&v=` + version + `"}], + "calendar_changes_url": "/calendar/changes.json?since=2026-08-18T11%3A00%3A00.000000Z"}`)) + default: + if r.URL.Query().Get("v") != "2" { + conflicts++ + w.WriteHeader(http.StatusConflict) + return + } + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{}`)) + } + })) + defer server.Close() + initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) + + // The list as the watch read it at its start, now in the SDK's cache; then HEY + // moves the recording feed to version 2. + if _, err := sdk.Calendars().ListWithChanges(context.Background()); err != nil { + t.Fatalf("unexpected error: %v", err) + } + mu.Lock() + version = "2" + mu.Unlock() + + watch, out := newTestWatch("recording_added", "calendar_resync") + watch.calendar = newTestCalendarsWatch(t, &watchedCalendar{id: 512, name: "Household", cursor: hey.CalendarChangesCursor{Since: "2026-08-18T11:00:00.000Z", Version: "1"}}) + + for range 2 { + if err := watch.readCalendar(context.Background(), watch.calendar.calendars[512]); err != nil { + t.Fatalf("unexpected error: %v", err) + } + } + + mu.Lock() + defer mu.Unlock() + if notModified != 0 || conflicts != 1 { + t.Errorf("list served from the cache %d times and the feed answered 409 %d times, want never and once", notModified, conflicts) + } + if got := watch.calendar.calendars[512].cursor.Version; got != "2" { + t.Errorf("version = %q, want the one HEY speaks now", got) + } + if lines := watchLines(t, out); len(lines) != 1 || lines[0]["change"] != watchCalendarResync { + t.Errorf("wrote %v, want one calendar_resync", lines) + } +} + func TestWatchCalendarStopsWatchingAGoneCalendar(t *testing.T) { t.Setenv("HEY_TOKEN", "test-token") diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index 55b9c5bd..bbb95994 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -546,17 +546,19 @@ func TestWatchSkipAheadEndsQuietlyWhenInterrupted(t *testing.T) { } } -// A box list the SDK revalidates answers 304 while no box row has changed, which is -// every posting's activity — so after a long drop the list hands back the since the -// watch fell behind from. Skipping to it answered 409 again on every read; skipping to -// HEY's clock gets past it. -func TestWatchSkipAheadGetsPastACachedBoxList(t *testing.T) { +// HEY's ETag for /boxes.json is the box rows, which neither posting activity nor a new +// feed version touches, so a list the SDK revalidates answers 304 with the since the +// watch fell behind from and the version HEY now refuses — and HEY answers 409 for a +// version it no longer speaks as surely as for too many changes. The skip-ahead reads +// the list past the cache: the next read is on HEY's clock and on the new version. +func TestWatchSkipAheadReadsTheBoxListPastTheCache(t *testing.T) { t.Setenv("HEY_TOKEN", "test-token") t.Setenv("XDG_CACHE_HOME", t.TempDir()) behind := time.Date(2026, 8, 21, 11, 0, 0, 0, time.UTC) // a since before this is too far behind var mu sync.Mutex var notModified, conflicts int + listed := `[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"/boxes/24088/postings/changes.json?since=2026-08-01T09%3A00%3A00.000000Z&v=2"}]` server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { mu.Lock() defer mu.Unlock() @@ -573,27 +575,31 @@ func TestWatchSkipAheadGetsPastACachedBoxList(t *testing.T) { return } w.Header().Set("Content-Type", "application/json") - _, _ = w.Write([]byte(`[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"/boxes/24088/postings/changes.json?since=2026-08-01T09%3A00%3A00.000000Z&v=2"}]`)) + _, _ = w.Write([]byte(listed)) default: since, _ := time.Parse(time.RFC3339Nano, r.URL.Query().Get("since")) - if since.Before(behind) { + if since.Before(behind) || r.URL.Query().Get("v") != "3" { // As HEY answers: `head :conflict`, no body. conflicts++ w.WriteHeader(http.StatusConflict) return } w.Header().Set("Content-Type", "application/json") - w.Header().Set("Link", `<`+r.URL.Path+`?since=2026-08-21T11%3A06%3A12.250000Z&v=2>; rel="next"`) + w.Header().Set("Link", `<`+r.URL.Path+`?since=2026-08-21T11%3A06%3A12.250000Z&v=3>; rel="next"`) _, _ = w.Write([]byte(`{"added":[{"id":9004,"kind":"topic","box_id":24088,"name":"Re: Lunch on Thursday?","active_at":"2026-08-21T11:06:12.250Z","created_at":"2026-08-21T11:06:12.250Z","creator":{"name":"Maria Delgado"}}]}`)) } })) defer server.Close() initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) - // The box list as the watch read it at its start, now in the SDK's cache. + // The box list as the watch read it at its start, now in the SDK's cache. Then HEY + // moves the feed to version 3, and the list's rows — its ETag — stay as they were. if _, err := sdk.Boxes().List(context.Background()); err != nil { t.Fatalf("unexpected error: %v", err) } + mu.Lock() + listed = `[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"/boxes/24088/postings/changes.json?since=2026-08-21T11%3A04%3A58.310442Z&v=3"}]` + mu.Unlock() watch, out := newTestWatch("added", "resync") cursor, err := watchCursor(server.URL+"/boxes/24088/postings/changes.json?since=2026-08-01T09%3A00%3A00.000000Z&v=2", "") @@ -607,12 +613,15 @@ func TestWatchSkipAheadGetsPastACachedBoxList(t *testing.T) { mu.Lock() defer mu.Unlock() - if notModified == 0 { - t.Fatal("the skip-ahead should have read the box list from the cache, as HEY answers a list whose rows have not changed") + if notModified != 0 { + t.Errorf("the skip-ahead read the box list from the cache %d times, want never — a 304 hands back the version HEY refused", notModified) } if conflicts != 1 { t.Errorf("the feed answered 409 %d times, want once — the skip-ahead should get past it", conflicts) } + if got := watch.boxes[24088].cursor.Version; got != "3" { + t.Errorf("version = %q, want the one HEY speaks now", got) + } lines := watchLines(t, out) if len(lines) != 2 || lines[0]["change"] != watchResync || lines[1]["change"] != "added" || lines[1]["posting_id"] != float64(9004) { t.Fatalf("wrote %v, want one resync and then the change after it", lines) From aa1d1bf31374c2d5514a01e5afc6b6ebe84cc213 Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 16:23:37 -0400 Subject: [PATCH 13/17] Retry a skip-ahead whose list read failed, and end it quietly on interrupt MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The clock read in a skip-ahead already told an interrupt from a failure, but the box and calendar list reads before it returned any error straight out of the watch: Ctrl-C or --timeout during the read exited with an error, and a passing 500 ended a watch that would have recovered on the next try. All three reads — the uncached client, the list and the clock — now go through skipFailed: an interrupt ends quietly, a permanent failure (credentials, a malformed request) still ends the watch, and anything else warns and retries on the backoff with the cursor where it was. The "too much changed ... skipping ahead" notice was printed before the skip was tried, so a skip that failed still claimed one. It now follows the skip, beside the resync line. --- internal/cmd/watch.go | 39 +++++---- internal/cmd/watch_calendar.go | 22 ++--- internal/cmd/watch_test.go | 144 +++++++++++++++++++++++++-------- 3 files changed, 144 insertions(+), 61 deletions(-) diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index 3ec2fcc6..14d0c725 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -665,13 +665,14 @@ func (w *postingsWatch) readBox(ctx context.Context, box *watchedBox) error { w.wasRead(box) if changes.FullSyncRequired { - fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipping ahead, read the box with `hey box view %s`\n", box.name, box.kind) skippedTo, skipped, err := w.skipAhead(ctx, box) if err != nil { return err } - // A resync says the box is worth re-reading; a box that is gone is not. + // A resync says the box is worth re-reading; a box that is gone is not, and a + // skip that has not happened yet — its retry is on the backoff — says nothing. if skipped { + fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, read the box with `hey box view %s`\n", box.name, box.kind) w.report(ctx, watchEvent{Change: watchResync, At: watchTime(skippedTo)}, box, nil) } return nil @@ -775,13 +776,14 @@ func (w *postingsWatch) settleBackoff() { // A clock that cannot be read leaves the cursor where it was, to be tried again on the // retry's backoff like any read that failed. func (w *postingsWatch) skipAhead(ctx context.Context, box *watchedBox) (time.Time, bool, error) { + later := func() { w.readAgainLater(box) } client, err := newUncachedSDKClient(ctx) if err != nil { - return time.Time{}, false, apierr.FromSDK(err) + return time.Time{}, false, w.skipFailed(ctx, box.name, err, later) } listed, err := client.Boxes().List(ctx) if err != nil { - return time.Time{}, false, apierr.FromSDK(err) + return time.Time{}, false, w.skipFailed(ctx, box.name, err, later) } if listed == nil { return time.Time{}, false, apierr.ErrAPI(0, "could not list boxes") @@ -801,16 +803,7 @@ func (w *postingsWatch) skipAhead(ctx context.Context, box *watchedBox) (time.Ti now, err := serverNowAnswered(ctx) if err != nil { - switch { - case ctx.Err() != nil: - return time.Time{}, false, nil //nolint:nilerr // an interrupt or a --timeout is how a watch is meant to end - case permanentReadError(err): - return time.Time{}, false, err - default: - fmt.Fprintf(w.errOut, "warning: could not skip %s ahead: %v\n", box.name, err) - w.readAgainLater(box) - return time.Time{}, false, nil - } + return time.Time{}, false, w.skipFailed(ctx, box.name, err, later) } cursor.Since = watchStartSince(now) box.cursor = cursor @@ -821,6 +814,24 @@ func (w *postingsWatch) skipAhead(ctx context.Context, box *watchedBox) (time.Ti return time.Time{}, false, w.stopWatching(box) } +// skipFailed says what a skip-ahead's failed read — its client, its list or HEY's +// clock — comes to: nothing, when the watch is being interrupted or timed out, which is +// how a watch is meant to end; the error, when waiting will not help; and otherwise a +// warning and the retry's backoff (later), with the cursor where it was. A 500 on the +// list is a reason to try again, not to stop watching. +func (w *postingsWatch) skipFailed(ctx context.Context, name string, err error, later func()) error { + switch { + case ctx.Err() != nil: + return nil //nolint:nilerr // an interrupt or a --timeout is how a watch is meant to end + case permanentReadError(err): + return apierr.FromSDK(err) + default: + fmt.Fprintf(w.errOut, "warning: could not skip %s ahead: %v\n", name, err) + later() + return nil + } +} + // stopWatching drops a box the watch can't follow any longer. When it was the last one // whose changes are reported there is nothing left to wait for — the others are only // followed for the record — and saying so beats a watch that sits there for good, diff --git a/internal/cmd/watch_calendar.go b/internal/cmd/watch_calendar.go index 0f8156c6..5c2c1a4f 100644 --- a/internal/cmd/watch_calendar.go +++ b/internal/cmd/watch_calendar.go @@ -326,12 +326,12 @@ func (w *postingsWatch) readCalendar(ctx context.Context, calendar *watchedCalen w.settleBackoff() if changes.FullSyncRequired { - fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipping ahead, re-read the calendar\n", calendar.name) skippedTo, skipped, err := w.skipCalendarAhead(ctx, calendar) if err != nil { return err } if skipped { + fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, re-read the calendar\n", calendar.name) w.reportCalendar(ctx, watchEvent{Change: watchCalendarResync, At: watchTime(skippedTo)}, calendar.id, calendar.name) } return nil @@ -381,13 +381,17 @@ func (w *postingsWatch) reportRecordings(ctx context.Context, calendar *watchedC // feed reports its deletion in its own time. A clock that cannot be read leaves the // cursor where it was, to be tried again on the retry's backoff. func (w *postingsWatch) skipCalendarAhead(ctx context.Context, calendar *watchedCalendar) (time.Time, bool, error) { + later := func() { + w.calendar.unread[calendar.id] = true + w.armRetry() + } client, err := newUncachedSDKClient(ctx) if err != nil { - return time.Time{}, false, apierr.FromSDK(err) + return time.Time{}, false, w.skipFailed(ctx, calendar.name, err, later) } list, err := client.Calendars().ListWithChanges(ctx) if err != nil { - return time.Time{}, false, apierr.FromSDK(err) + return time.Time{}, false, w.skipFailed(ctx, calendar.name, err, later) } if list == nil { return time.Time{}, false, apierr.ErrAPI(0, "could not list calendars") @@ -404,17 +408,7 @@ func (w *postingsWatch) skipCalendarAhead(ctx context.Context, calendar *watched now, err := serverNowAnswered(ctx) if err != nil { - switch { - case ctx.Err() != nil: - return time.Time{}, false, nil //nolint:nilerr // an interrupt or a --timeout is how a watch is meant to end - case permanentReadError(err): - return time.Time{}, false, err - default: - fmt.Fprintf(w.errOut, "warning: could not skip %s ahead: %v\n", calendar.name, err) - w.calendar.unread[calendar.id] = true - w.armRetry() - return time.Time{}, false, nil - } + return time.Time{}, false, w.skipFailed(ctx, calendar.name, err, later) } cursor.Since = watchStartSince(now) calendar.cursor = cursor diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index bbb95994..0346bceb 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -13,6 +13,7 @@ import ( "slices" "strings" "sync" + "sync/atomic" "testing" "time" @@ -480,16 +481,20 @@ func TestWatchSkipsAheadToHEYsClock(t *testing.T) { } } -// cancelledAtTheClock is HEY as a skip-ahead meets it when the watch is interrupted -// while it reads the clock: the feed is too far behind, the box and calendar lists -// answer, and the clock request is where the interrupt lands. -func cancelledAtTheClock(t *testing.T, cancel context.CancelFunc) { +// skipHEY is HEY as a skip-ahead meets it: the feed too far behind, and the box list, +// the calendar list and the clock answering — save the reads fail answers itself, which +// it says it did by returning true. +func skipHEY(t *testing.T, fail func(http.ResponseWriter, *http.Request) bool) { t.Helper() server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if fail(w, r) { + return + } switch r.URL.Path { case "/identity.json": - cancel() - <-r.Context().Done() + w.Header().Set("Date", skipDate) + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{"id":1}`)) case "/boxes.json": w.Header().Set("Content-Type", "application/json") _, _ = w.Write([]byte(`[{"id":24088,"kind":"imbox","name":"Imbox","posting_changes_url":"/boxes/24088/postings/changes.json?since=2026-08-21T11%3A02%3A00.518496Z&v=2"}]`)) @@ -506,41 +511,114 @@ func cancelledAtTheClock(t *testing.T, cancel context.CancelFunc) { initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) } -// An interrupt or --timeout while a skip-ahead reads HEY's clock is how a watch is -// meant to end, not a failed read: nothing is warned about and no retry is armed. +// behindWatch is a watch whose Imbox and Household calendar have both fallen too far +// behind to follow. +func behindWatch(t *testing.T) (*postingsWatch, *bytes.Buffer, *bytes.Buffer) { + t.Helper() + watch, out := newTestWatch("added", "resync", "calendar_resync") + errOut := &bytes.Buffer{} + watch.errOut = errOut + watch.boxes[24088].cursor.Since = "2026-08-01T00:00:00.000Z" + watch.calendar = newTestCalendarsWatch(t, &watchedCalendar{id: 512, name: "Household", cursor: hey.CalendarChangesCursor{Since: "2026-08-01T00:00:00.000Z", Version: "1"}}) + return watch, out, errOut +} + +// readBehind reads the box or the calendar behindWatch left behind. +func readBehind(ctx context.Context, watch *postingsWatch, feed string) error { + if feed == "box" { + return watch.readBox(ctx, watch.boxes[24088]) + } + return watch.readCalendar(ctx, watch.calendar.calendars[512]) +} + +// listOf is the list a skip-ahead reads for a feed. +func listOf(feed string) string { + if feed == "box" { + return "/boxes.json" + } + return "/calendars.json" +} + +// An interrupt or --timeout while a skip-ahead reads its list or HEY's clock is how a +// watch is meant to end, not a failed read: nothing is warned about, no retry is armed, +// and nothing says it skipped. func TestWatchSkipAheadEndsQuietlyWhenInterrupted(t *testing.T) { + for _, feed := range []string{"box", "calendar"} { + for _, at := range []string{"/identity.json", listOf(feed)} { + t.Run(feed+at, func(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + skipHEY(t, func(w http.ResponseWriter, r *http.Request) bool { + if r.URL.Path != at { + return false + } + cancel() + <-r.Context().Done() + return true + }) + watch, out, errOut := behindWatch(t) + + if err := readBehind(ctx, watch, feed); err != nil { + t.Fatalf("read = %v, want an interrupted skip-ahead to end quietly", err) + } + if errOut.Len() != 0 { + t.Errorf("stderr = %q, want nothing for an interrupt", errOut.String()) + } + if watch.retry != nil || len(watch.unread) != 0 || len(watch.calendar.unread) != 0 { + t.Error("an interrupted skip-ahead should not arm a retry") + } + if out.Len() != 0 { + t.Errorf("wrote %q, want no resync for a skip that did not happen", out.String()) + } + if watch.boxes[24088].cursor.Since != "2026-08-01T00:00:00.000Z" || watch.calendar.calendars[512].cursor.Since != "2026-08-01T00:00:00.000Z" { + t.Error("an interrupted skip-ahead should leave the cursor where it was") + } + }) + } + } +} + +// A list that fails to read for a while is a reason to try the skip again, not to stop +// watching: the watch warns, keeps the cursor, retries on the backoff, and says it +// skipped only once it has. +func TestWatchSkipAheadRetriesAListThatFailed(t *testing.T) { for _, feed := range []string{"box", "calendar"} { t.Run(feed, func(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) - defer cancel() - cancelledAtTheClock(t, cancel) - - watch, out := newTestWatch("added", "resync", "calendar_resync") - errOut := &bytes.Buffer{} - watch.errOut = errOut - watch.boxes[24088].cursor.Since = "2026-08-01T00:00:00.000Z" - watch.calendar = newTestCalendarsWatch(t, &watchedCalendar{id: 512, name: "Household", cursor: hey.CalendarChangesCursor{Since: "2026-08-01T00:00:00.000Z", Version: "1"}}) - - var err error - if feed == "box" { - err = watch.readBox(ctx, watch.boxes[24088]) - } else { - err = watch.readCalendar(ctx, watch.calendar.calendars[512]) - } - if err != nil { - t.Fatalf("read = %v, want an interrupted skip-ahead to end quietly", err) + var down atomic.Bool + down.Store(true) + skipHEY(t, func(w http.ResponseWriter, r *http.Request) bool { + if r.URL.Path != listOf(feed) || !down.Load() { + return false + } + http.Error(w, "down for maintenance", http.StatusInternalServerError) + return true + }) + watch, out, errOut := behindWatch(t) + + if err := readBehind(context.Background(), watch, feed); err != nil { + t.Fatalf("read = %v, want a failed list read retried, not the watch ended", err) } - if strings.Contains(errOut.String(), "warning") { - t.Errorf("stderr = %q, want no warning for an interrupt", errOut.String()) + if !strings.Contains(errOut.String(), "warning: could not skip") || strings.Contains(errOut.String(), "notice") { + t.Errorf("stderr = %q, want a warning and no word of a skip that has not happened", errOut.String()) } - if watch.retry != nil || len(watch.unread) != 0 || len(watch.calendar.unread) != 0 { - t.Error("an interrupted skip-ahead should not arm a retry") + if watch.retry == nil || len(watch.unread)+len(watch.calendar.unread) != 1 { + t.Fatal("a failed list read should be retried on the backoff") } if out.Len() != 0 { - t.Errorf("wrote %q, want no resync for a skip that did not happen", out.String()) + t.Errorf("wrote %q, want no resync before the skip", out.String()) + } + + // The list is back: the retry skips, and says so once. + down.Store(false) + errOut.Reset() + if err := watch.retryUnread(context.Background()); err != nil { + t.Fatalf("retry = %v", err) + } + if lines := watchLines(t, out); len(lines) != 1 || !strings.HasSuffix(lines[0]["change"].(string), "resync") { + t.Errorf("wrote %v, want one resync once the skip happened", lines) } - if watch.boxes[24088].cursor.Since != "2026-08-01T00:00:00.000Z" || watch.calendar.calendars[512].cursor.Since != "2026-08-01T00:00:00.000Z" { - t.Error("an interrupted skip-ahead should leave the cursor where it was") + if !strings.Contains(errOut.String(), "notice: too much changed") { + t.Errorf("stderr = %q, want the skip announced once it happened", errOut.String()) } }) } From 7f61bdec6a7a2acfd4f8852d12e8b6239fd4c403 Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 16:26:12 -0400 Subject: [PATCH 14/17] Report one resync per catch-up, and hold repeated skips for the backoff MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A skip-ahead lands on HEY's clock at the whole second before its Date header. A feed busy enough to carry more than an increment's worth of changes after that answers 409 again on the next read, and every doorbell after it — as many as the feed was changing — read, skipped and reported another resync with no delay between them. A feed's recovery from a 409 is now one episode (feedRecovery). The first skip is announced with its notice and its resync line and counts as the feed read. A 409 straight after it skips again without a word and leaves the box or calendar on the retry backoff, which doubles while the feed stays that busy; doorbells for it wait for that retry rather than skipping it again. A clean read ends the episode, and the next 409 after that is a recovery of its own. The help text, docs/cli.md, the skill and AGENTS.md say one resync covers the whole catch-up. --- AGENTS.md | 13 +++-- docs/cli.md | 3 +- internal/cmd/watch.go | 61 ++++++++++++++++++------ internal/cmd/watch_calendar.go | 57 +++++++++++++++------- internal/cmd/watch_test.go | 87 ++++++++++++++++++++++++++++++++++ skills/hey/SKILL.md | 3 +- 6 files changed, 185 insertions(+), 39 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 7293b839..40e7035c 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -696,10 +696,15 @@ it is the reader's. The Date header is whole seconds, so the start can be up to serves says the time finer — Action Cable pings are whole seconds too — and rounding the other way would skip changes. A 409 skip-ahead moves the cursor to HEY's clock when it answered (`serverNowAnswered` — not taken back by the request's time, since a resync has -no gap to catch and a slow request could leave a busy feed still behind; and not the box -list's since, which the ETag cache can serve unchanged and would 409 again) and sets that box's floor there (`newMail.skippedTo`): activity at or before it -is never new there, known thread or not, because the watch never read the gap. A calendar's -409 skips the same way. `resync` is an event of its own — reported by default, +no gap to catch and a slow request could leave a busy feed still behind), keeping the feed +version from a list read past the SDK's cache (`newUncachedSDKClient`: the list's ETag is +its rows, which neither posting activity nor a new feed version changes, and HEY answers +409 for a version it no longer speaks), and sets that box's floor there +(`newMail.skippedTo`): activity at or before it is never new there, known thread or not, +because the watch never read the gap. A 409 straight after a skip is the same recovery +(`feedRecovery`): no second resync, and the next skip waits on the retry backoff rather +than every doorbell. A list or clock read that fails is retried on that backoff, and an +interrupt during one ends quietly (`skipFailed`). A calendar's 409 skips the same way. `resync` is an event of its own — reported by default, left out by `--events new` — so a script for new mail never runs on one. The Omarchy bar plugin toasts from those lines itself (app-name, glyph, click-to-focus and the replace-not-stack id all live in the plugin), and nothing desktop-shaped lives in `watch*.go`. diff --git a/docs/cli.md b/docs/cli.md index b10ace00..c369e69f 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -366,7 +366,8 @@ calendar — `{"change":"recording_added","calendar":{"id":512,"name":"Household "recording_id":88001,"recording_type":"Calendar::Event","recording":{}}` — and a calendar arriving, changing or leaving is `calendar_added`, `calendar_updated` or `calendar_deleted`. A calendar whose feed fell too far behind is skipped ahead and says so -with `calendar_resync`, the way a box says `resync`. The email-specific flags switch the +with `calendar_resync`, the way a box says `resync`. Either is said once per catch-up: a +feed still too busy after the skip is skipped again on the retry backoff, quietly. The email-specific flags switch the calendars off: `--box` scopes the watch to mail, and an `--events` list naming only mail changes does the same. diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index 14d0c725..207028ec 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -102,7 +102,8 @@ Besides the thread changes, three lines describe the watch itself: "ready" once and calendar is caught up and the subscription is live (again after every reconnect's catch-up), "disconnected" when the connection drops, and "resync" when a box changed more than the feed can list one change at a time and the watch skipped ahead — re-read that -box. A resync is an event of its own: reported by default, scripts run for it and +box. One resync covers the whole catch-up: a box still too busy after the skip is skipped +again on the retry backoff without another. A resync is an event of its own: reported by default, scripts run for it and --exit-on-first counts it, and --events can leave it out, as --events new does. A calendar's feed falls behind the same way, and calendar_resync is the same word for it. Ready and disconnected are written to stdout only.`, @@ -357,6 +358,18 @@ type watchedBox struct { name string cursor hey.PostingChangesCursor reported bool // --box named it, or named nothing + recovery feedRecovery +} + +// feedRecovery is how far a box's or a calendar's feed is into getting back from a 409. +// One skip-ahead usually does it; a feed busier than that — more than an increment's +// worth of changes after HEY's clock at the skip — answers 409 again straight after. +// That is one episode, not several: the resync is reported once, and the skips after +// it wait on the retry backoff rather than following every doorbell, which would ring +// as fast as the feed is changing. A clean read ends the episode. +type feedRecovery struct { + resynced bool // the episode's resync is out + holding bool // skipped again straight after: the retry, not a doorbell, reads next } // watchEvent is one changed posting or calendar recording, as a line of NDJSON or as a @@ -637,7 +650,9 @@ func (w *postingsWatch) read(ctx context.Context, message actioncable.Message) e return nil } - if box, watching := w.boxes[notification.BoxID]; watching { + // A box holding for its retry after a repeated 409 is read by the retry: a doorbell + // would only skip it ahead again. + if box, watching := w.boxes[notification.BoxID]; watching && !box.recovery.holding { if err := w.readBox(ctx, box); err != nil { return err } @@ -662,21 +677,11 @@ func (w *postingsWatch) readBox(ctx context.Context, box *watchedBox) error { return nil } } - w.wasRead(box) - if changes.FullSyncRequired { - skippedTo, skipped, err := w.skipAhead(ctx, box) - if err != nil { - return err - } - // A resync says the box is worth re-reading; a box that is gone is not, and a - // skip that has not happened yet — its retry is on the backoff — says nothing. - if skipped { - fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, read the box with `hey box view %s`\n", box.name, box.kind) - w.report(ctx, watchEvent{Change: watchResync, At: watchTime(skippedTo)}, box, nil) - } - return nil + return w.recoverBox(ctx, box) } + w.wasRead(box) + box.recovery = feedRecovery{} if changes.NextCursor != nil { box.cursor = *changes.NextCursor @@ -700,6 +705,32 @@ func (w *postingsWatch) readBox(ctx context.Context, box *watchedBox) error { return nil } +// recoverBox gets a box that answered 409 back onto its feed by skipping it ahead. The +// first skip of an episode is announced — the notice, and the resync line that is the +// reader's cue to re-read the box — and counts as the box read. A 409 straight after +// it skips again without a word, and leaves the box behind on the retry backoff, which +// doubles while the feed stays too busy to follow. A box that is gone is not worth +// re-reading, and a skip that has not happened — its retry is on the backoff — says +// nothing. +func (w *postingsWatch) recoverBox(ctx context.Context, box *watchedBox) error { + skippedTo, skipped, err := w.skipAhead(ctx, box) + if err != nil || !skipped { + return err + } + + if box.recovery.resynced { + box.recovery.holding = true + w.readAgainLater(box) + return nil + } + box.recovery.resynced = true + w.wasRead(box) + fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, read the box with `hey box view %s`\n", box.name, box.kind) + w.report(ctx, watchEvent{Change: watchResync, At: watchTime(skippedTo)}, box, nil) + + return nil +} + // classify decides whether a posting is new mail and records it, in that order. func (w *postingsWatch) classify(box *watchedBox, posting generated.Posting) *bool { isNew := w.newMail.isNew(box.id, posting) diff --git a/internal/cmd/watch_calendar.go b/internal/cmd/watch_calendar.go index 5c2c1a4f..050de094 100644 --- a/internal/cmd/watch_calendar.go +++ b/internal/cmd/watch_calendar.go @@ -46,11 +46,12 @@ const ( // watchedCalendar is one calendar the watch follows: how far its recording feed has been // read, and the stream that rings when it changes. type watchedCalendar struct { - id int64 - name string - cursor hey.CalendarChangesCursor - stream string - stop context.CancelFunc + id int64 + name string + cursor hey.CalendarChangesCursor + stream string + stop context.CancelFunc + recovery feedRecovery } // calendarsWatch is the calendar half of a watch: the calendars and their cursors, the @@ -268,7 +269,8 @@ func (w *postingsWatch) coalesceCalendarRing() { func (w *postingsWatch) readRungCalendars(ctx context.Context) error { w.calendar.due = nil for _, id := range w.calendar.take() { - if calendar, watching := w.calendar.calendars[id]; watching { + // A calendar holding for its retry after a repeated 409 is read by the retry. + if calendar, watching := w.calendar.calendars[id]; watching && !calendar.recovery.holding { if err := w.readCalendar(ctx, calendar); err != nil { return err } @@ -322,20 +324,11 @@ func (w *postingsWatch) readCalendar(ctx context.Context, calendar *watchedCalen return nil } } - delete(w.calendar.unread, calendar.id) - w.settleBackoff() - if changes.FullSyncRequired { - skippedTo, skipped, err := w.skipCalendarAhead(ctx, calendar) - if err != nil { - return err - } - if skipped { - fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, re-read the calendar\n", calendar.name) - w.reportCalendar(ctx, watchEvent{Change: watchCalendarResync, At: watchTime(skippedTo)}, calendar.id, calendar.name) - } - return nil + return w.recoverCalendar(ctx, calendar) } + w.calendarWasRead(calendar) + calendar.recovery = feedRecovery{} if changes.NextCursor != nil { calendar.cursor = *changes.NextCursor @@ -355,6 +348,34 @@ func (w *postingsWatch) readCalendar(ctx context.Context, calendar *watchedCalen return nil } +// recoverCalendar is recoverBox for a calendar's recording feed: one calendar_resync +// per episode, and a repeated 409 skipped again on the retry backoff. +func (w *postingsWatch) recoverCalendar(ctx context.Context, calendar *watchedCalendar) error { + skippedTo, skipped, err := w.skipCalendarAhead(ctx, calendar) + if err != nil || !skipped { + return err + } + + if calendar.recovery.resynced { + calendar.recovery.holding = true + w.calendar.unread[calendar.id] = true + w.armRetry() + return nil + } + calendar.recovery.resynced = true + w.calendarWasRead(calendar) + fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, re-read the calendar\n", calendar.name) + w.reportCalendar(ctx, watchEvent{Change: watchCalendarResync, At: watchTime(skippedTo)}, calendar.id, calendar.name) + + return nil +} + +// calendarWasRead takes a calendar off the retry list once it is caught up. +func (w *postingsWatch) calendarWasRead(calendar *watchedCalendar) { + delete(w.calendar.unread, calendar.id) + w.settleBackoff() +} + // reportRecordings walks one bucket in type order, so a read reports the same changes in // the same order every time. func (w *postingsWatch) reportRecordings(ctx context.Context, calendar *watchedCalendar, change string, bucket map[string][]generated.Recording, at func(generated.Recording) time.Time) { diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index 0346bceb..058ff901 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -624,6 +624,93 @@ func TestWatchSkipAheadRetriesAListThatFailed(t *testing.T) { } } +// A feed busier than one skip can outrun answers 409 again straight after the skip. That +// is one recovery: one resync line and one notice, and the skips after it wait on the +// retry backoff — doubling — rather than following every doorbell. +func TestWatchRecoversFromARepeated409Once(t *testing.T) { + for _, feed := range []string{"box", "calendar"} { + t.Run(feed, func(t *testing.T) { + var feedReads atomic.Int32 + var quiet atomic.Bool + skipHEY(t, func(w http.ResponseWriter, r *http.Request) bool { + if !strings.Contains(r.URL.Path, "/changes") { + return false + } + feedReads.Add(1) + if !quiet.Load() { + return false // 409, as HEY answers for a feed this busy + } + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{}`)) + return true + }) + watch, out, errOut := behindWatch(t) + ring := func() { + t.Helper() + var err error + if feed == "box" { + err = watch.read(context.Background(), actioncable.Message(`{"change":"upsert","box_id":24088}`)) + } else { + watch.calendar.ring(512) + <-watch.calendar.wake + err = watch.readRungCalendars(context.Background()) + } + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + } + + for range 5 { + ring() + } + if got := feedReads.Load(); got != 2 { + t.Errorf("read the feed %d times for five doorbells, want twice — the second 409 holds the rest for the retry", got) + } + if lines := watchLines(t, out); len(lines) != 1 || !strings.HasSuffix(lines[0]["change"].(string), "resync") { + t.Errorf("wrote %v, want one resync for the whole recovery", lines) + } + if got := strings.Count(errOut.String(), "notice: too much changed"); got != 1 { + t.Errorf("stderr = %q, want the skip announced once", errOut.String()) + } + if watch.retry == nil || watch.backoff != firstWatchRetry { + t.Fatalf("backoff = %v, want the repeat held for the first retry", watch.backoff) + } + + // The retry comes round, as the loop runs it: another 409, another skip, + // the same recovery, and a longer wait before the next. + watch.retry = nil + if err := watch.retryUnread(context.Background()); err != nil { + t.Fatalf("unexpected error: %v", err) + } + if got := feedReads.Load(); got != 3 { + t.Errorf("read the feed %d times, want the retry's read too", got) + } + if lines := watchLines(t, out); len(lines) != 1 { + t.Errorf("wrote %v, want still one resync", lines) + } + if watch.backoff != 2*firstWatchRetry { + t.Errorf("backoff = %v, want it doubled while the feed stays too busy", watch.backoff) + } + + // The feed quietens and a clean read ends the recovery; the next time it + // falls behind is a recovery of its own, with its own resync. + quiet.Store(true) + watch.retry = nil + if err := watch.retryUnread(context.Background()); err != nil { + t.Fatalf("unexpected error: %v", err) + } + if len(watch.unread)+len(watch.calendar.unread) != 0 { + t.Error("a clean read should leave nothing behind") + } + quiet.Store(false) + ring() + if lines := watchLines(t, out); len(lines) != 2 { + t.Errorf("wrote %v, want a second resync for a second recovery", lines) + } + }) + } +} + // HEY's ETag for /boxes.json is the box rows, which neither posting activity nor a new // feed version touches, so a list the SDK revalidates answers 304 with the since the // watch fell behind from and the version HEY now refuses — and HEY answers 409 for a diff --git a/skills/hey/SKILL.md b/skills/hey/SKILL.md index c950f52a..ef9cbb31 100644 --- a/skills/hey/SKILL.md +++ b/skills/hey/SKILL.md @@ -724,7 +724,8 @@ posting carries no `posting`, `thread_id` or `new`. Three more lines describe the watch itself: `{"change": "ready"}` once every box and calendar is caught up and the subscription is live (again after every reconnect's catch-up), `{"change": "disconnected"}` when the connection drops, and `{"change": "resync", "box": {...}}` when a box changed more than the -feed can list and the watch skipped ahead — re-read that box. A resync is an event of its +feed can list and the watch skipped ahead — re-read that box; one resync covers the whole +catch-up, however many skips it takes. A resync is an event of its own: reported by default (`--run-*` scripts run for it, `--exit-on-first` counts it) and left out by `--events new`, so a script for new mail never runs on one. `ready` and `disconnected` carry no `box`, are written only when no `--run-*` command is given, and never count for From 702f6476f79a2c744bf0467d6138855dff7ab858 Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 16:26:42 -0400 Subject: [PATCH 15/17] Narrow what the docs say about HEY's finer clocks The docs said nothing HEY serves gives a finer time than the Date header. A posting doorbell's at (Posting::Broadcasting, iso8601_with_ms) and the feeds' cursors carry microseconds, but only once something has changed, never as a now before the watch starts. AGENTS.md and serverNow now say that. docs/omarchy.md also said a box's first read carries only what arrived while the watch was starting; it now includes the whole-second window described just before it. --- AGENTS.md | 8 +++++--- docs/omarchy.md | 7 ++++--- internal/cmd/watch_new.go | 9 ++++++--- 3 files changed, 15 insertions(+), 9 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 40e7035c..268c6e74 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -692,9 +692,11 @@ cutoff every feed and new mail are measured against, since a fast one would skip a slow one would report history. That is HEY's semantics and state across events, so the CLI decides it once; what to do about it is the reader's. The Date header is whole seconds, so the start can be up to a second -(plus the clock request's whole time, retries included) early and a change from that window is reported; nothing HEY -serves says the time finer — Action Cable pings are whole seconds too — and rounding the -other way would skip changes. A 409 skip-ahead moves the cursor to HEY's clock when it +(plus the clock request's whole time, retries included) early and a change from that window +is reported. Nothing HEY serves on demand says the time finer — Action Cable pings are +whole seconds too; a posting doorbell's `at` and the feeds' cursors carry microseconds, but +only once something has changed, never as a "now" before the watch starts — and rounding +the other way would skip changes. A 409 skip-ahead moves the cursor to HEY's clock when it answered (`serverNowAnswered` — not taken back by the request's time, since a resync has no gap to catch and a slow request could leave a busy feed still behind), keeping the feed version from a list read past the SDK's cache (`newUncachedSDKClient`: the list's ETag is diff --git a/docs/omarchy.md b/docs/omarchy.md index 4157449c..979476f8 100644 --- a/docs/omarchy.md +++ b/docs/omarchy.md @@ -202,9 +202,10 @@ and `--events new` selects the true ones. The rule: into a box is never new, and a reply on a known thread is. A box's first read starts at the watch's start, not at the server's cursor — the box's last posting activity, which a deletion or a bundled posting can postdate, and which a cached box list can serve days - old — so it carries only what arrived while the - watch was starting, which is new. `--since` reads backlog first, which the start-time - rule keeps out. + old — so it carries what arrived while the watch was starting, which is new, and at most + the whole-second window above: a change from just before the start that the start could + not be told apart from. `--since` reads backlog first, which the start-time rule keeps + out. - **Every posting the watch reads is recorded**, in every box and whatever `--events` or `--box` reports — `--box` picks what is reported, every box is followed — so a thread known from a filtered-out change, or from another box, is never mistaken for new when its diff --git a/internal/cmd/watch_new.go b/internal/cmd/watch_new.go index 57766094..e77b87d1 100644 --- a/internal/cmd/watch_new.go +++ b/internal/cmd/watch_new.go @@ -71,9 +71,12 @@ func (n *newMail) skippedTo(boxID int64, cursor hey.PostingChangesCursor) { // calling mail a moment old new rather than mail a moment new old. That is a // window of up to a second, plus the request's own time: a change from that // long before the watch began is after the start, so it is read, reported and -// can be new, and --exit-on-first can stop on it. Nothing HEY serves says the -// time any finer — Action Cable's pings are whole seconds too, and no JSON -// answer carries a server "now" — and rounding the other way would skip up to +// can be new, and --exit-on-first can stop on it. Nothing HEY serves on demand +// says the time any finer: Action Cable's pings are whole seconds, and no JSON +// answer carries a server "now". Finer times do exist — a posting doorbell's at +// and a feed's cursors are to the microsecond — but only once something has +// changed, which is no use for the moment a watch starts. And rounding the +// other way would skip up to // a second of changes that did come after the start, which is worse than // repeating one that did not. A reader who cares can tell from the line's at. // The SDK caches GETs by URL, so a query the server ignores keeps this one out From 691370fce95191995a9b023aa3d1a2aa7a9b5219 Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 16:36:11 -0400 Subject: [PATCH 16/17] Hold a feed whose skip-ahead failed for the retry, not the next doorbell A skip-ahead whose list or clock read failed put the box or calendar on the retry backoff, but doorbells kept reading it: each one met the same 409 and made the same failing requests, and the backoff waited for nothing. The failed skip now marks the feed holding, as a repeated 409 does, so doorbells leave it to the retry. A skip that lands clears the hold, and the feed follows its doorbells again. --- internal/cmd/watch.go | 9 ++++-- internal/cmd/watch_calendar.go | 4 ++- internal/cmd/watch_test.go | 53 ++++++++++++++++++++++++---------- 3 files changed, 48 insertions(+), 18 deletions(-) diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index 207028ec..4ddf4fd8 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -723,7 +723,7 @@ func (w *postingsWatch) recoverBox(ctx context.Context, box *watchedBox) error { w.readAgainLater(box) return nil } - box.recovery.resynced = true + box.recovery = feedRecovery{resynced: true} w.wasRead(box) fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, read the box with `hey box view %s`\n", box.name, box.kind) w.report(ctx, watchEvent{Change: watchResync, At: watchTime(skippedTo)}, box, nil) @@ -807,7 +807,12 @@ func (w *postingsWatch) settleBackoff() { // A clock that cannot be read leaves the cursor where it was, to be tried again on the // retry's backoff like any read that failed. func (w *postingsWatch) skipAhead(ctx context.Context, box *watchedBox) (time.Time, bool, error) { - later := func() { w.readAgainLater(box) } + // A skip that could not be made is tried again by the retry, not by the next doorbell, + // which would only meet the same 409 and the same failing read. + later := func() { + box.recovery.holding = true + w.readAgainLater(box) + } client, err := newUncachedSDKClient(ctx) if err != nil { return time.Time{}, false, w.skipFailed(ctx, box.name, err, later) diff --git a/internal/cmd/watch_calendar.go b/internal/cmd/watch_calendar.go index 050de094..f63b6d1c 100644 --- a/internal/cmd/watch_calendar.go +++ b/internal/cmd/watch_calendar.go @@ -362,7 +362,7 @@ func (w *postingsWatch) recoverCalendar(ctx context.Context, calendar *watchedCa w.armRetry() return nil } - calendar.recovery.resynced = true + calendar.recovery = feedRecovery{resynced: true} w.calendarWasRead(calendar) fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, re-read the calendar\n", calendar.name) w.reportCalendar(ctx, watchEvent{Change: watchCalendarResync, At: watchTime(skippedTo)}, calendar.id, calendar.name) @@ -402,7 +402,9 @@ func (w *postingsWatch) reportRecordings(ctx context.Context, calendar *watchedC // feed reports its deletion in its own time. A clock that cannot be read leaves the // cursor where it was, to be tried again on the retry's backoff. func (w *postingsWatch) skipCalendarAhead(ctx context.Context, calendar *watchedCalendar) (time.Time, bool, error) { + // Tried again by the retry, not by the next ring — as for a box. later := func() { + calendar.recovery.holding = true w.calendar.unread[calendar.id] = true w.armRetry() } diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index 058ff901..f128b264 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -531,6 +531,23 @@ func readBehind(ctx context.Context, watch *postingsWatch, feed string) error { return watch.readCalendar(ctx, watch.calendar.calendars[512]) } +// ringFeed rings the doorbell for the box or the calendar behindWatch left behind, and +// answers it the way the watch's loop does. +func ringFeed(t *testing.T, watch *postingsWatch, feed string) { + t.Helper() + var err error + if feed == "box" { + err = watch.read(context.Background(), actioncable.Message(`{"change":"upsert","box_id":24088}`)) + } else { + watch.calendar.ring(512) + <-watch.calendar.wake + err = watch.readRungCalendars(context.Background()) + } + if err != nil { + t.Fatalf("unexpected error: %v", err) + } +} + // listOf is the list a skip-ahead reads for a feed. func listOf(feed string) string { if feed == "box" { @@ -585,9 +602,14 @@ func TestWatchSkipAheadRetriesAListThatFailed(t *testing.T) { for _, feed := range []string{"box", "calendar"} { t.Run(feed, func(t *testing.T) { var down atomic.Bool + var listReads atomic.Int32 down.Store(true) skipHEY(t, func(w http.ResponseWriter, r *http.Request) bool { - if r.URL.Path != listOf(feed) || !down.Load() { + if r.URL.Path != listOf(feed) { + return false + } + listReads.Add(1) + if !down.Load() { return false } http.Error(w, "down for maintenance", http.StatusInternalServerError) @@ -608,6 +630,13 @@ func TestWatchSkipAheadRetriesAListThatFailed(t *testing.T) { t.Errorf("wrote %q, want no resync before the skip", out.String()) } + // Doorbells wait for the retry rather than trying the failing list again. + ringFeed(t, watch, feed) + ringFeed(t, watch, feed) + if got := listReads.Load(); got != 1 { + t.Errorf("read the list %d times, want once — the retry, not a doorbell, tries again", got) + } + // The list is back: the retry skips, and says so once. down.Store(false) errOut.Reset() @@ -620,6 +649,13 @@ func TestWatchSkipAheadRetriesAListThatFailed(t *testing.T) { if !strings.Contains(errOut.String(), "notice: too much changed") { t.Errorf("stderr = %q, want the skip announced once it happened", errOut.String()) } + + // Skipped, the feed follows its doorbells again. + reads := listReads.Load() + ringFeed(t, watch, feed) + if listReads.Load() == reads { + t.Error("a doorbell after the skip should read the feed again") + } }) } } @@ -645,20 +681,7 @@ func TestWatchRecoversFromARepeated409Once(t *testing.T) { return true }) watch, out, errOut := behindWatch(t) - ring := func() { - t.Helper() - var err error - if feed == "box" { - err = watch.read(context.Background(), actioncable.Message(`{"change":"upsert","box_id":24088}`)) - } else { - watch.calendar.ring(512) - <-watch.calendar.wake - err = watch.readRungCalendars(context.Background()) - } - if err != nil { - t.Fatalf("unexpected error: %v", err) - } - } + ring := func() { ringFeed(t, watch, feed) } for range 5 { ring() From f07e7ffd136a4ba842fea3f195e505965fa3a9a2 Mon Sep 17 00:00:00 2001 From: Rob Zolkos Date: Sat, 26 Sep 2026 16:50:45 -0400 Subject: [PATCH 17/17] Send a recovery's resync with the clean read that ends it A recovery announced its resync at its first skip and stayed quiet for the skips after it. A reader that re-read the box on that resync could then be left stale: a later skip in the same recovery passed over changes that were neither reported nor followed by another cue to re-read. The resync now goes out when the recovery ends, with the first clean read, after every skip it took; its at is the last skip. So that a skip that works first time is not left waiting for the next doorbell, the first skip of a recovery is read from straight away. A 409 on that read, or on any later one, still waits on the retry backoff. Boxes and calendars alike. --- AGENTS.md | 8 ++- docs/cli.md | 5 +- internal/cmd/watch.go | 44 ++++++++------- internal/cmd/watch_calendar.go | 20 ++++--- internal/cmd/watch_calendar_test.go | 2 +- internal/cmd/watch_test.go | 88 +++++++++++++++++++---------- skills/hey/SKILL.md | 2 +- 7 files changed, 106 insertions(+), 63 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 268c6e74..eb9755c6 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -703,9 +703,11 @@ version from a list read past the SDK's cache (`newUncachedSDKClient`: the list' its rows, which neither posting activity nor a new feed version changes, and HEY answers 409 for a version it no longer speaks), and sets that box's floor there (`newMail.skippedTo`): activity at or before it is never new there, known thread or not, -because the watch never read the gap. A 409 straight after a skip is the same recovery -(`feedRecovery`): no second resync, and the next skip waits on the retry backoff rather -than every doorbell. A list or clock read that fails is retried on that backoff, and an +because the watch never read the gap. The first skip is read from straight away; a 409 +after it is the same recovery (`feedRecovery`), and the next skip waits on the retry +backoff rather than every doorbell. The recovery's one resync goes out with the clean read +that ends it, at the last skip, so a reader that re-reads on it has missed nothing a later +skip passed. A list or clock read that fails is retried on that backoff, and an interrupt during one ends quietly (`skipFailed`). A calendar's 409 skips the same way. `resync` is an event of its own — reported by default, left out by `--events new` — so a script for new mail never runs on one. The Omarchy bar plugin toasts from those lines itself (app-name, glyph, click-to-focus and the replace-not-stack id all live in the plugin), and nothing diff --git a/docs/cli.md b/docs/cli.md index c369e69f..63a8e8a7 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -366,8 +366,9 @@ calendar — `{"change":"recording_added","calendar":{"id":512,"name":"Household "recording_id":88001,"recording_type":"Calendar::Event","recording":{}}` — and a calendar arriving, changing or leaving is `calendar_added`, `calendar_updated` or `calendar_deleted`. A calendar whose feed fell too far behind is skipped ahead and says so -with `calendar_resync`, the way a box says `resync`. Either is said once per catch-up: a -feed still too busy after the skip is skipped again on the retry backoff, quietly. The email-specific flags switch the +with `calendar_resync`, the way a box says `resync`. Either is said once per catch-up, when +the feed can be followed again: a feed still too busy after the skip is skipped again on the +retry backoff, and the line's `at` is the last skip. The email-specific flags switch the calendars off: `--box` scopes the watch to mail, and an `--events` list naming only mail changes does the same. diff --git a/internal/cmd/watch.go b/internal/cmd/watch.go index 4ddf4fd8..ce0b17c7 100644 --- a/internal/cmd/watch.go +++ b/internal/cmd/watch.go @@ -102,8 +102,9 @@ Besides the thread changes, three lines describe the watch itself: "ready" once and calendar is caught up and the subscription is live (again after every reconnect's catch-up), "disconnected" when the connection drops, and "resync" when a box changed more than the feed can list one change at a time and the watch skipped ahead — re-read that -box. One resync covers the whole catch-up: a box still too busy after the skip is skipped -again on the retry backoff without another. A resync is an event of its own: reported by default, scripts run for it and +box. One resync covers the whole catch-up and comes once the box is followed again: a box +still too busy after the skip is skipped again on the retry backoff, and its "at" is the +last skip. A resync is an event of its own: reported by default, scripts run for it and --exit-on-first counts it, and --events can leave it out, as --events new does. A calendar's feed falls behind the same way, and calendar_resync is the same word for it. Ready and disconnected are written to stdout only.`, @@ -364,12 +365,14 @@ type watchedBox struct { // feedRecovery is how far a box's or a calendar's feed is into getting back from a 409. // One skip-ahead usually does it; a feed busier than that — more than an increment's // worth of changes after HEY's clock at the skip — answers 409 again straight after. -// That is one episode, not several: the resync is reported once, and the skips after -// it wait on the retry backoff rather than following every doorbell, which would ring -// as fast as the feed is changing. A clean read ends the episode. +// That is one episode, not several. Its skips after the first wait on the retry backoff +// rather than following every doorbell, which would ring as fast as the feed is +// changing, and its one resync goes out with the clean read that ends it: after every +// skip it took, so a reader that re-reads on it is not left stale by a later one. type feedRecovery struct { - resynced bool // the episode's resync is out - holding bool // skipped again straight after: the retry, not a doorbell, reads next + skipped bool // the episode has skipped ahead + skippedTo time.Time // where its last skip landed: the resync's at + holding bool // the retry, not a doorbell, reads the feed next } // watchEvent is one changed posting or calendar recording, as a line of NDJSON or as a @@ -681,6 +684,9 @@ func (w *postingsWatch) readBox(ctx context.Context, box *watchedBox) error { return w.recoverBox(ctx, box) } w.wasRead(box) + if box.recovery.skipped { + w.report(ctx, watchEvent{Change: watchResync, At: watchTime(box.recovery.skippedTo)}, box, nil) + } box.recovery = feedRecovery{} if changes.NextCursor != nil { @@ -706,29 +712,29 @@ func (w *postingsWatch) readBox(ctx context.Context, box *watchedBox) error { } // recoverBox gets a box that answered 409 back onto its feed by skipping it ahead. The -// first skip of an episode is announced — the notice, and the resync line that is the -// reader's cue to re-read the box — and counts as the box read. A 409 straight after -// it skips again without a word, and leaves the box behind on the retry backoff, which -// doubles while the feed stays too busy to follow. A box that is gone is not worth -// re-reading, and a skip that has not happened — its retry is on the backoff — says -// nothing. +// first skip of an episode is announced on stderr and read from straight away, since +// one skip usually lands on a feed the watch can follow; the resync line, the reader's +// cue to re-read the box, goes out with the clean read (readBox). A 409 after a skip +// skips again without a word and leaves the box on the retry backoff, which doubles +// while the feed stays too busy to follow. A box that is gone is not worth re-reading, +// and a skip that has not happened — its retry is on the backoff — says nothing. func (w *postingsWatch) recoverBox(ctx context.Context, box *watchedBox) error { skippedTo, skipped, err := w.skipAhead(ctx, box) if err != nil || !skipped { return err } - if box.recovery.resynced { + first := !box.recovery.skipped + box.recovery.skipped = true + box.recovery.skippedTo = skippedTo + if !first { box.recovery.holding = true w.readAgainLater(box) return nil } - box.recovery = feedRecovery{resynced: true} - w.wasRead(box) - fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, read the box with `hey box view %s`\n", box.name, box.kind) - w.report(ctx, watchEvent{Change: watchResync, At: watchTime(skippedTo)}, box, nil) - return nil + fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, read the box with `hey box view %s`\n", box.name, box.kind) + return w.readBox(ctx, box) } // classify decides whether a posting is new mail and records it, in that order. diff --git a/internal/cmd/watch_calendar.go b/internal/cmd/watch_calendar.go index f63b6d1c..3dc53053 100644 --- a/internal/cmd/watch_calendar.go +++ b/internal/cmd/watch_calendar.go @@ -328,6 +328,9 @@ func (w *postingsWatch) readCalendar(ctx context.Context, calendar *watchedCalen return w.recoverCalendar(ctx, calendar) } w.calendarWasRead(calendar) + if calendar.recovery.skipped { + w.reportCalendar(ctx, watchEvent{Change: watchCalendarResync, At: watchTime(calendar.recovery.skippedTo)}, calendar.id, calendar.name) + } calendar.recovery = feedRecovery{} if changes.NextCursor != nil { @@ -348,26 +351,27 @@ func (w *postingsWatch) readCalendar(ctx context.Context, calendar *watchedCalen return nil } -// recoverCalendar is recoverBox for a calendar's recording feed: one calendar_resync -// per episode, and a repeated 409 skipped again on the retry backoff. +// recoverCalendar is recoverBox for a calendar's recording feed: the first skip is read +// from straight away, a 409 after a skip waits on the retry backoff, and the episode's +// one calendar_resync goes out with the clean read that ends it. func (w *postingsWatch) recoverCalendar(ctx context.Context, calendar *watchedCalendar) error { skippedTo, skipped, err := w.skipCalendarAhead(ctx, calendar) if err != nil || !skipped { return err } - if calendar.recovery.resynced { + first := !calendar.recovery.skipped + calendar.recovery.skipped = true + calendar.recovery.skippedTo = skippedTo + if !first { calendar.recovery.holding = true w.calendar.unread[calendar.id] = true w.armRetry() return nil } - calendar.recovery = feedRecovery{resynced: true} - w.calendarWasRead(calendar) - fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, re-read the calendar\n", calendar.name) - w.reportCalendar(ctx, watchEvent{Change: watchCalendarResync, At: watchTime(skippedTo)}, calendar.id, calendar.name) - return nil + fmt.Fprintf(w.errOut, "notice: too much changed in %s to follow one change at a time — skipped ahead, re-read the calendar\n", calendar.name) + return w.readCalendar(ctx, calendar) } // calendarWasRead takes a calendar off the retry list once it is caught up. diff --git a/internal/cmd/watch_calendar_test.go b/internal/cmd/watch_calendar_test.go index 64354edf..90b67325 100644 --- a/internal/cmd/watch_calendar_test.go +++ b/internal/cmd/watch_calendar_test.go @@ -269,7 +269,7 @@ func TestWatchCalendarSkipsAheadOnAFullSync(t *testing.T) { _, _ = w.Write([]byte(`{"id":1}`)) return } - w.WriteHeader(http.StatusConflict) + answerTooFarBehindBefore(w, r, time.Date(2026, 8, 21, 11, 0, 0, 0, time.UTC)) })) defer server.Close() initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) diff --git a/internal/cmd/watch_test.go b/internal/cmd/watch_test.go index f128b264..560d3bea 100644 --- a/internal/cmd/watch_test.go +++ b/internal/cmd/watch_test.go @@ -481,9 +481,10 @@ func TestWatchSkipsAheadToHEYsClock(t *testing.T) { } } -// skipHEY is HEY as a skip-ahead meets it: the feed too far behind, and the box list, -// the calendar list and the clock answering — save the reads fail answers itself, which -// it says it did by returning true. +// skipHEY is HEY as a skip-ahead meets it: a feed read from before 11:00 too far behind +// to follow and one from after it clean, and the box list, the calendar list and the +// clock answering — save the reads fail answers itself, which it says it did by +// returning true. func skipHEY(t *testing.T, fail func(http.ResponseWriter, *http.Request) bool) { t.Helper() server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { @@ -503,7 +504,7 @@ func skipHEY(t *testing.T, fail func(http.ResponseWriter, *http.Request) bool) { _, _ = w.Write([]byte(`{"calendars": [{"calendar": {"id": 512, "name": "Household"}, "recording_changes_url": "/calendars/512/recording/changes.json?since=2026-08-18T11%3A00%3A00.000000Z&v=1"}]}`)) default: - w.WriteHeader(http.StatusConflict) + answerTooFarBehindBefore(w, r, time.Date(2026, 8, 21, 11, 0, 0, 0, time.UTC)) } })) t.Cleanup(server.Close) @@ -511,6 +512,19 @@ func skipHEY(t *testing.T, fail func(http.ResponseWriter, *http.Request) bool) { initSDK(auth.NewManager(server.URL, server.Client(), t.TempDir()), server.URL) } +// answerTooFarBehindBefore answers a changes feed read as HEY would for a feed that +// changed too much before behind to follow — `head :conflict`, no body — and not at +// all since. +func answerTooFarBehindBefore(w http.ResponseWriter, r *http.Request, behind time.Time) { + since, err := time.Parse(time.RFC3339Nano, r.URL.Query().Get("since")) + if err != nil || since.Before(behind) { + w.WriteHeader(http.StatusConflict) + return + } + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{}`)) +} + // behindWatch is a watch whose Imbox and Household calendar have both fallen too far // behind to follow. func behindWatch(t *testing.T) (*postingsWatch, *bytes.Buffer, *bytes.Buffer) { @@ -602,9 +616,12 @@ func TestWatchSkipAheadRetriesAListThatFailed(t *testing.T) { for _, feed := range []string{"box", "calendar"} { t.Run(feed, func(t *testing.T) { var down atomic.Bool - var listReads atomic.Int32 + var listReads, feedReads atomic.Int32 down.Store(true) skipHEY(t, func(w http.ResponseWriter, r *http.Request) bool { + if strings.Contains(r.URL.Path, "/changes") { + feedReads.Add(1) + } if r.URL.Path != listOf(feed) { return false } @@ -637,7 +654,8 @@ func TestWatchSkipAheadRetriesAListThatFailed(t *testing.T) { t.Errorf("read the list %d times, want once — the retry, not a doorbell, tries again", got) } - // The list is back: the retry skips, and says so once. + // The list is back: the retry skips, reads the feed from there, and says so + // once. down.Store(false) errOut.Reset() if err := watch.retryUnread(context.Background()); err != nil { @@ -651,9 +669,9 @@ func TestWatchSkipAheadRetriesAListThatFailed(t *testing.T) { } // Skipped, the feed follows its doorbells again. - reads := listReads.Load() + reads := feedReads.Load() ringFeed(t, watch, feed) - if listReads.Load() == reads { + if feedReads.Load() == reads { t.Error("a doorbell after the skip should read the feed again") } }) @@ -661,8 +679,9 @@ func TestWatchSkipAheadRetriesAListThatFailed(t *testing.T) { } // A feed busier than one skip can outrun answers 409 again straight after the skip. That -// is one recovery: one resync line and one notice, and the skips after it wait on the -// retry backoff — doubling — rather than following every doorbell. +// is one recovery: one notice, skips after the first waiting on the retry backoff — +// doubling — rather than following every doorbell, and one resync line, when a clean +// read ends it, so a reader that re-reads on it has missed nothing a later skip passed. func TestWatchRecoversFromARepeated409Once(t *testing.T) { for _, feed := range []string{"box", "calendar"} { t.Run(feed, func(t *testing.T) { @@ -673,11 +692,10 @@ func TestWatchRecoversFromARepeated409Once(t *testing.T) { return false } feedReads.Add(1) - if !quiet.Load() { - return false // 409, as HEY answers for a feed this busy + if quiet.Load() { + return false } - w.Header().Set("Content-Type", "application/json") - _, _ = w.Write([]byte(`{}`)) + w.WriteHeader(http.StatusConflict) // as HEY answers for a feed this busy return true }) watch, out, errOut := behindWatch(t) @@ -687,10 +705,10 @@ func TestWatchRecoversFromARepeated409Once(t *testing.T) { ring() } if got := feedReads.Load(); got != 2 { - t.Errorf("read the feed %d times for five doorbells, want twice — the second 409 holds the rest for the retry", got) + t.Errorf("read the feed %d times for five doorbells, want twice — the skip's own read, then the rest held for the retry", got) } - if lines := watchLines(t, out); len(lines) != 1 || !strings.HasSuffix(lines[0]["change"].(string), "resync") { - t.Errorf("wrote %v, want one resync for the whole recovery", lines) + if lines := watchLines(t, out); len(lines) != 0 { + t.Errorf("wrote %v, want the resync kept for the clean read that ends the recovery", lines) } if got := strings.Count(errOut.String(), "notice: too much changed"); got != 1 { t.Errorf("stderr = %q, want the skip announced once", errOut.String()) @@ -708,25 +726,39 @@ func TestWatchRecoversFromARepeated409Once(t *testing.T) { if got := feedReads.Load(); got != 3 { t.Errorf("read the feed %d times, want the retry's read too", got) } - if lines := watchLines(t, out); len(lines) != 1 { - t.Errorf("wrote %v, want still one resync", lines) + if out.Len() != 0 { + t.Errorf("wrote %q, want still nothing while the feed stays too busy", out.String()) } if watch.backoff != 2*firstWatchRetry { t.Errorf("backoff = %v, want it doubled while the feed stays too busy", watch.backoff) } - // The feed quietens and a clean read ends the recovery; the next time it - // falls behind is a recovery of its own, with its own resync. - quiet.Store(true) - watch.retry = nil - if err := watch.retryUnread(context.Background()); err != nil { - t.Fatalf("unexpected error: %v", err) + // The feed quietens and a clean read ends the recovery with its one resync, + // at the last skip; the next time it falls behind is a recovery of its own. + retryClean := func() { + t.Helper() + quiet.Store(true) + watch.retry = nil + if err := watch.retryUnread(context.Background()); err != nil { + t.Fatalf("unexpected error: %v", err) + } + quiet.Store(false) } + retryClean() if len(watch.unread)+len(watch.calendar.unread) != 0 { t.Error("a clean read should leave nothing behind") } - quiet.Store(false) + lines := watchLines(t, out) + if len(lines) != 1 || !strings.HasSuffix(lines[0]["change"].(string), "resync") { + t.Fatalf("wrote %v, want one resync for the whole recovery", lines) + } + skippedTo, err := time.Parse(time.RFC3339Nano, lines[0]["at"].(string)) + if err != nil { + t.Fatalf("resync at %v: %v", lines[0]["at"], err) + } + wantSkippedToHEYsClock(t, skippedTo) ring() + retryClean() if lines := watchLines(t, out); len(lines) != 2 { t.Errorf("wrote %v, want a second resync for a second recovery", lines) } @@ -796,7 +828,6 @@ func TestWatchSkipAheadReadsTheBoxListPastTheCache(t *testing.T) { } watch.boxes[24088].cursor = cursor - ringBox(t, watch) ringBox(t, watch) mu.Lock() @@ -1563,8 +1594,7 @@ func TestWatchReportsAResyncAfterSkippingAhead(t *testing.T) { var server *httptest.Server server = httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { if strings.Contains(r.URL.Path, "/postings/changes") { - // As HEY answers: `head :conflict`, no body. - w.WriteHeader(http.StatusConflict) + answerTooFarBehindBefore(w, r, time.Date(2026, 8, 21, 11, 0, 0, 0, time.UTC)) return } w.Header().Set("Date", skipDate) diff --git a/skills/hey/SKILL.md b/skills/hey/SKILL.md index ef9cbb31..32e67f4e 100644 --- a/skills/hey/SKILL.md +++ b/skills/hey/SKILL.md @@ -725,7 +725,7 @@ describe the watch itself: `{"change": "ready"}` once every box and calendar is is live (again after every reconnect's catch-up), `{"change": "disconnected"}` when the connection drops, and `{"change": "resync", "box": {...}}` when a box changed more than the feed can list and the watch skipped ahead — re-read that box; one resync covers the whole -catch-up, however many skips it takes. A resync is an event of its +catch-up, however many skips it takes, and comes once the box is followed again. A resync is an event of its own: reported by default (`--run-*` scripts run for it, `--exit-on-first` counts it) and left out by `--events new`, so a script for new mail never runs on one. `ready` and `disconnected` carry no `box`, are written only when no `--run-*` command is given, and never count for