Carry the event's receipt time into every delivery (closes #257) #297

clawbot · 2026-08-24T06:28:36+02:00

clawbot commented

2026-08-24 06:28:36 +02:00

Closes #257.

The defect

Every Slack/Mattermost message rendered *Timestamp:* as 0001-01-01T00:00:00Z while the stored event's created_at was correct. Both delivery paths reconstruct the event from the Task that carries it; no Task carries a receipt time, so FormatSlackMessage formatted a zero time.Time.

Why not a `Task` field

Task is built in three places: buildRecoveryTask (internal/delivery/engine.go), buildDeliveryTasks (internal/handlers/webhook.go) and createReplayDelivery (internal/handlers/delivery_replay.go). Only the first is the restart-recovery path. A new field populated in internal/delivery alone would have fixed recovery and left the live first-attempt and replay paths — the ones that produce essentially every message a human reads — still zero. That is the half-fix this defect invites.

The stored row is the single source of truth instead: resolveEventBody becomes hydrateEvent, which reads created_at alongside body. Both processNewTask and processRetryTask already call it, so every reconstruction path is covered regardless of where its Task came from, and Task is unchanged.

(Task is neither serialised nor persisted — it has no struct tags and travels only through the deliveryCh/retryCh buffered channels — so widening it would have been safe; it just would not have worked.)

The ownership gate (#256) and the terminal-state paths (#107) are untouched.

Behaviour change worth reviewing

A task that inlined its body previously made no database read at all on the first attempt. It makes one now. A read failure on that path is deliberately not fatal: the event row can be reaped by retention while a queued delivery still holds its body inline, and dropping a deliverable event to protect one metadata field is a worse failure than the one it prevents. Such a delivery goes out with the timestamp unset and a warning logged. A task with no inlined body still fails, exactly as before.

`buildEventFromTask` field audit (issue's second ask)

database.Event has 12 fields. Before this change:

Field	Populated?	User-visible when zero
`ID`	yes	—
`WebhookID`	yes	—
`EntrypointID`	yes	—
`Method`	yes	—
`Headers`	yes	—
`ContentType`	yes	—
`Body`	yes, via `resolveEventBody`	—
`CreatedAt`	no	yes — this defect
`UpdatedAt`	no	no
`DeletedAt`	no	no
`ResubmittedFromID`	no	no
`Webhook` / `Entrypoint` / `Deliveries` (relations)	no	no

Consumers of the reconstructed event across all four targets: target_slack.go reads Method, ContentType, CreatedAt, Body; target_http.go reads Body, ContentType, Headers; target_log.go reads WebhookID, EntrypointID, Method, ContentType, Headers, Body; target_database.go reads ID, WebhookID, EntrypointID, Method, Headers, Body, ContentType.

CreatedAt was the only user-visible gap and is the only one fixed here. UpdatedAt, DeletedAt and ResubmittedFromID are read by no target on this path; they are reported, not fixed, per the scope fence.

One observation for the owner rather than a filed defect: the archivedEvent row the database target writes records ArchivedAt but not the event's original receipt time, so an archive cannot say when a webhook actually arrived. That reads as a deliberate schema choice rather than an oversight, and adding a column is beyond this issue either way — flagging it as a question, not a bug.

Verification

Reproduced on unmodified next first. Raw payload captured from a sink standing in for the Slack incoming webhook, identical on all three paths:

{"text":"*Webhook Event Received*\n*Method:* `POST`\n*Content-Type:* `application/json`\n*Timestamp:* `0001-01-01T00:00:00Z`\n*Body Size:* 17 bytes\n..."}

After the fix, same sink, event seeded with created_at of 2026-03-04T05:06:07Z (chosen so it can be confused with neither the zero time nor "roughly now"):

{"text":"*Webhook Event Received*\n*Method:* `POST`\n*Content-Type:* `application/json`\n*Timestamp:* `2026-03-04T05:06:07Z`\n*Body Size:* 17 bytes\n..."}

New tests in internal/delivery/event_timestamp_test.go:

TestSlackFirstAttemptCarriesEventTimestamp — first-attempt path, body inlined.
TestSlackFirstAttemptLargeBodyCarriesEventTimestamp — first-attempt path, body read back from the row.
TestSlackRetryCarriesEventTimestamp — retry path, via processRetryTask on a retrying delivery.
TestFormatSlackMessageOverTaskReconstructedEvent — unit-level, asserts a non-zero and correct timestamp in FormatSlackMessage output over an event reconstructed from a Task.
TestEventReconstructionSurvivesAReapedRow — pins the fallback above in both directions.

Mutation-verified: with event.CreatedAt = dbEvent.CreatedAt removed, the first four fail and the fallback test still passes, which is the correct split.

make check green with GOFLAGS=-count=1: 21 packages ok, zero (cached) lines, and the lint stage executed rather than replaying (#11 [lint 3/3] RUN ... golangci-lint run, 62s, 0 issues.).

TODO.md is untouched, per its own Workflow section (issue branches do not edit it).

Closes https://git.eeqj.de/sneak/webhooker/issues/257. ## The defect Every Slack/Mattermost message rendered `*Timestamp:*` as `0001-01-01T00:00:00Z` while the stored event's `created_at` was correct. Both delivery paths reconstruct the event from the `Task` that carries it; no `Task` carries a receipt time, so `FormatSlackMessage` formatted a zero `time.Time`. ## Why not a `Task` field `Task` is built in three places: `buildRecoveryTask` (`internal/delivery/engine.go`), `buildDeliveryTasks` (`internal/handlers/webhook.go`) and `createReplayDelivery` (`internal/handlers/delivery_replay.go`). Only the first is the restart-recovery path. A new field populated in `internal/delivery` alone would have fixed recovery and left the live first-attempt and replay paths — the ones that produce essentially every message a human reads — still zero. That is the half-fix this defect invites. The stored row is the single source of truth instead: `resolveEventBody` becomes `hydrateEvent`, which reads `created_at` alongside `body`. Both `processNewTask` and `processRetryTask` already call it, so every reconstruction path is covered regardless of where its `Task` came from, and `Task` is unchanged. (`Task` is neither serialised nor persisted — it has no struct tags and travels only through the `deliveryCh`/`retryCh` buffered channels — so widening it would have been safe; it just would not have worked.) The ownership gate (https://git.eeqj.de/sneak/webhooker/issues/256) and the terminal-state paths (https://git.eeqj.de/sneak/webhooker/issues/107) are untouched. ## Behaviour change worth reviewing A task that inlined its body previously made no database read at all on the first attempt. It makes one now. A read failure on that path is deliberately **not** fatal: the event row can be reaped by retention while a queued delivery still holds its body inline, and dropping a deliverable event to protect one metadata field is a worse failure than the one it prevents. Such a delivery goes out with the timestamp unset and a warning logged. A task with no inlined body still fails, exactly as before. ## `buildEventFromTask` field audit (issue's second ask) `database.Event` has 12 fields. Before this change: | Field | Populated? | User-visible when zero | |---|---|---| | `ID` | yes | — | | `WebhookID` | yes | — | | `EntrypointID` | yes | — | | `Method` | yes | — | | `Headers` | yes | — | | `ContentType` | yes | — | | `Body` | yes, via `resolveEventBody` | — | | `CreatedAt` | **no** | **yes — this defect** | | `UpdatedAt` | no | no | | `DeletedAt` | no | no | | `ResubmittedFromID` | no | no | | `Webhook` / `Entrypoint` / `Deliveries` (relations) | no | no | Consumers of the reconstructed event across all four targets: `target_slack.go` reads `Method`, `ContentType`, `CreatedAt`, `Body`; `target_http.go` reads `Body`, `ContentType`, `Headers`; `target_log.go` reads `WebhookID`, `EntrypointID`, `Method`, `ContentType`, `Headers`, `Body`; `target_database.go` reads `ID`, `WebhookID`, `EntrypointID`, `Method`, `Headers`, `Body`, `ContentType`. `CreatedAt` was the only user-visible gap and is the only one fixed here. `UpdatedAt`, `DeletedAt` and `ResubmittedFromID` are read by no target on this path; they are reported, not fixed, per the scope fence. One observation for the owner rather than a filed defect: the `archivedEvent` row the database target writes records `ArchivedAt` but not the event's original receipt time, so an archive cannot say when a webhook actually arrived. That reads as a deliberate schema choice rather than an oversight, and adding a column is beyond this issue either way — flagging it as a question, not a bug. ## Verification Reproduced on unmodified `next` first. Raw payload captured from a sink standing in for the Slack incoming webhook, identical on all three paths: ``` {"text":"*Webhook Event Received*\n*Method:* `POST`\n*Content-Type:* `application/json`\n*Timestamp:* `0001-01-01T00:00:00Z`\n*Body Size:* 17 bytes\n..."} ``` After the fix, same sink, event seeded with `created_at` of `2026-03-04T05:06:07Z` (chosen so it can be confused with neither the zero time nor "roughly now"): ``` {"text":"*Webhook Event Received*\n*Method:* `POST`\n*Content-Type:* `application/json`\n*Timestamp:* `2026-03-04T05:06:07Z`\n*Body Size:* 17 bytes\n..."} ``` New tests in `internal/delivery/event_timestamp_test.go`: - `TestSlackFirstAttemptCarriesEventTimestamp` — first-attempt path, body inlined. - `TestSlackFirstAttemptLargeBodyCarriesEventTimestamp` — first-attempt path, body read back from the row. - `TestSlackRetryCarriesEventTimestamp` — retry path, via `processRetryTask` on a `retrying` delivery. - `TestFormatSlackMessageOverTaskReconstructedEvent` — unit-level, asserts a non-zero and correct timestamp in `FormatSlackMessage` output over an event reconstructed from a `Task`. - `TestEventReconstructionSurvivesAReapedRow` — pins the fallback above in both directions. Mutation-verified: with `event.CreatedAt = dbEvent.CreatedAt` removed, the first four fail and the fallback test still passes, which is the correct split. `make check` green with `GOFLAGS=-count=1`: 21 packages `ok`, zero `(cached)` lines, and the lint stage executed rather than replaying (`#11 [lint 3/3] RUN ... golangci-lint run`, 62s, `0 issues.`). `TODO.md` is untouched, per its own Workflow section (issue branches do not edit it).

clawbot added 1 commit 2026-08-24 06:28:37 +02:00

Carry the event's receipt time into every delivery (closes #257 )

check / check (push) Successful in 3m59s

Details

62b9463827

Every Slack and Mattermost message the engine sent rendered a
`*Timestamp:*` of `0001-01-01T00:00:00Z` while the stored event's
`created_at` was correct. Both delivery paths reconstruct the event
from the Task that carries it, and no Task carries a receipt time, so
`FormatSlackMessage` formatted a zero `time.Time`.

`Task` is not the place to fix it: it is built in three places, two of
them on the receiver side, and a field there would have left the live
first-attempt and retry paths still zero while only the restart
recovery path came out correct. The stored row stays the single source
of truth instead. `resolveEventBody` becomes `hydrateEvent` and reads
`created_at` alongside the body, so every path that reconstructs an
event gets the receipt time with it.

A task that inlined its body previously never read the event row. It
does now, and a read failure there is no longer fatal: the row can be
reaped by retention while a queued delivery still holds its body, and
such a delivery goes out with the timestamp unset rather than being
dropped. A task with no inlined body still fails, as before.

clawbot added the needs-review label 2026-08-24 06:28:44 +02:00

clawbot self-assigned this 2026-08-24 06:28:44 +02:00

clawbot referenced this pull request

2026-08-24 06:28:51 +02:00

Every Slack message shows a zero timestamp of 0001-01-01T00:00:00Z #257

clawbot commented

2026-08-24 06:43:35 +02:00

PASS. Independently reproduced the zero timestamp on unmodified next and confirmed the fix on all five reconstruction paths (first attempt inlined, first attempt from the row, retry, restart recovery, replay), with a seeded created_at of 2026-03-04T05:06:07Z — the rendered value is the receipt time, not the delivery time. Mutation-verified both directions. #256 non-regression: 900 deliveries (300 events x 3 targets), unique body per delivery, 900 sink POSTs, 0 duplicates, max(attempt_num)=1, inflight.held()=0, x3 runs; restart plus both sweep arms (each proven to select rows) added zero. make check green locally with GOFLAGS=-count=1 (21 packages ok, 0 (cached), lint executed in Docker, 65s, 0 issues.); CI green on 62b9463; make fmt a no-op; commit hygiene and attribution clean; mergeable, no rebase needed.

Two notes for the owner, neither blocking.

The reaped-row fallback is the right call, but the human sees *Timestamp:* `0001-01-01T00:00:00Z` in that case — FormatSlackMessage (internal/delivery/target_slack.go:236) emits the line unconditionally, so the fallback renders the exact string #257 was filed against and is indistinguishable from a regression. Verified end to end: with the event row hard-deleted, the delivery goes out, could not read the stored event logs at WARN, payload carries the zero stamp. Suggested follow-up (not this PR): omit or mark the line when CreatedAt is zero. The scenario is real — reapExpired (internal/database/retention.go:273-320) hard-deletes events on created_at < cutoff with no delivery-status guard; the practical trigger is an operator lowering a webhook's RetentionDays, since retention is day-granular.
Hot-path cost, measured: the added SELECT created_at is 33 us per delivery (20k warm primary-key reads, median 32.9 us). End-to-end inlined-body first attempts ran 641-889/s on next and 610-846/s on this branch over 3 runs each — the delta is inside shared-host noise. The read uses the same pooled per-webhook handle as the existing writes (WAL, 10s busy timeout, 4 max conns), and under WAL a reader cannot block a writer, so it cannot recreate the wedge; no write errors or SQLITE_BUSY appeared across the 900-delivery runs. Worth knowing: 3 of the 4 target types never read CreatedAt and now pay the read anyway.

Ownership: hydrateEvent takes and releases no reference and adds no path that terminalises a delivery outside takeForRedispatch; the new failure branch returns nil, so it can only make a delivery more likely to proceed, never less. Field audit spot-checked and correct — no target reads UpdatedAt, DeletedAt or ResubmittedFromID off a reconstructed event, and the database target builds its archive row from named fields, so populating CreatedAt cannot change what it writes.

Disclosure: all probes ran in throwaway copies of the tree, never on the reviewed checkout; the reviewed tree is unmodified.

PASS. Independently reproduced the zero timestamp on unmodified `next` and confirmed the fix on all five reconstruction paths (first attempt inlined, first attempt from the row, retry, restart recovery, replay), with a seeded `created_at` of `2026-03-04T05:06:07Z` — the rendered value is the receipt time, not the delivery time. Mutation-verified both directions. https://git.eeqj.de/sneak/webhooker/issues/256 non-regression: 900 deliveries (300 events x 3 targets), unique body per delivery, 900 sink POSTs, 0 duplicates, `max(attempt_num)`=1, `inflight.held()`=0, x3 runs; restart plus both sweep arms (each proven to select rows) added zero. `make check` green locally with `GOFLAGS=-count=1` (21 packages `ok`, 0 `(cached)`, lint executed in Docker, 65s, `0 issues.`); CI green on `62b9463`; `make fmt` a no-op; commit hygiene and attribution clean; mergeable, no rebase needed. Two notes for the owner, neither blocking. 1. The reaped-row fallback is the right call, but the human sees `*Timestamp:* `0001-01-01T00:00:00Z`` in that case — `FormatSlackMessage` (`internal/delivery/target_slack.go:236`) emits the line unconditionally, so the fallback renders the exact string https://git.eeqj.de/sneak/webhooker/issues/257 was filed against and is indistinguishable from a regression. Verified end to end: with the event row hard-deleted, the delivery goes out, `could not read the stored event` logs at WARN, payload carries the zero stamp. Suggested follow-up (not this PR): omit or mark the line when `CreatedAt` is zero. The scenario is real — `reapExpired` (`internal/database/retention.go:273-320`) hard-deletes events on `created_at < cutoff` with no delivery-status guard; the practical trigger is an operator lowering a webhook's `RetentionDays`, since retention is day-granular. 2. Hot-path cost, measured: the added `SELECT created_at` is 33 us per delivery (20k warm primary-key reads, median 32.9 us). End-to-end inlined-body first attempts ran 641-889/s on `next` and 610-846/s on this branch over 3 runs each — the delta is inside shared-host noise. The read uses the same pooled per-webhook handle as the existing writes (WAL, 10s busy timeout, 4 max conns), and under WAL a reader cannot block a writer, so it cannot recreate the wedge; no write errors or `SQLITE_BUSY` appeared across the 900-delivery runs. Worth knowing: 3 of the 4 target types never read `CreatedAt` and now pay the read anyway. Ownership: `hydrateEvent` takes and releases no reference and adds no path that terminalises a delivery outside `takeForRedispatch`; the new failure branch returns `nil`, so it can only make a delivery more likely to proceed, never less. Field audit spot-checked and correct — no target reads `UpdatedAt`, `DeletedAt` or `ResubmittedFromID` off a reconstructed event, and the database target builds its archive row from named fields, so populating `CreatedAt` cannot change what it writes. Disclosure: all probes ran in throwaway copies of the tree, never on the reviewed checkout; the reviewed tree is unmodified.

clawbot merged commit 5976a4a98f into next

2026-08-24 06:44:24 +02:00

clawbot deleted branch issue-257-slack-timestamp

2026-08-24 06:44:24 +02:00

clawbot referenced this pull request

2026-08-24 06:44:38 +02:00

The reaped-row fallback renders the exact zero timestamp that #257 was filed against #298

clawbot referenced this pull request

2026-08-24 06:44:52 +02:00

Startup recovery races the receiver and can deliver a fresh event twice #299

Sign in to join this conversation.