From 92dbfc89968ee1838d887e05881f3fcbcf01af96 Mon Sep 17 00:00:00 2001 From: sneak Date: Sat, 3 Oct 2026 00:52:03 +0000 Subject: [PATCH] Event log: show attempt and delivery times, label replays, zone event times (closes #386) Each attempt shows when it was recorded and each delivery when it was created, in the event log and on the event's page. The event log's event times read as the recent events list does: how long ago, with the full UTC time on hover. A delivery records whether Replay created it, in a new replay column added to the delivery model in place. Such a delivery is labelled a replay in the event's summary line and in both pages' delivery lists. Model: opus-5-5 --- README.md | 8 +++- internal/database/model_delivery.go | 4 ++ internal/handlers/delivery_replay.go | 1 + internal/handlers/delivery_replay_test.go | 46 ++++++++++++++++++++ internal/handlers/delivery_result_view.go | 8 ++++ internal/handlers/event_log_times_test.go | 52 +++++++++++++++++++++++ internal/handlers/event_log_view.go | 11 ++++- internal/handlers/source_management.go | 13 ++++++ internal/handlers/target_list.go | 3 +- templates/delivery_attempts.html | 1 + templates/event_detail.html | 8 +++- templates/source_logs.html | 6 ++- 12 files changed, 152 insertions(+), 9 deletions(-) create mode 100644 internal/handlers/event_log_times_test.go diff --git a/README.md b/README.md index 2b2f6bc..1d38ba3 100644 --- a/README.md +++ b/README.md @@ -1830,6 +1830,7 @@ status across potentially multiple attempts. | `target_id`| UUID | Foreign key → Target | | `status` | DeliveryStatus | One of: `pending`, `delivered`, `failed`, `retrying` | | `finished_at` | timestamp | When the delivery became `delivered` or `failed` (nullable; empty while `pending` or `retrying`) | +| `replay` | boolean | Whether the delivery was created by **Replay** | **Relations:** Belongs to Event. Belongs to Target. Has many DeliveryResults. @@ -1849,7 +1850,8 @@ NEW `pending` delivery for the same event and target and hands it to the engine on the ordinary path — same retries, same SSRF guard, same circuit breaker as a first attempt. It never touches the delivery it repeats: that row's status, timestamps and recorded attempts stand as -the record of what happened. +the record of what happened. The new delivery records `replay`, and the +event log and the event's page label it a replay. What is re-sent is the stored event body, against the target's configuration **as it stands now** — the point of a replay is to @@ -1903,6 +1905,10 @@ A `database` or `log` target sends no HTTP request, so in the event log and on the event's page its attempts show no status: a successful one reads "archived" or "written to the log". +The event log and the event's page show when each attempt was recorded and +when each delivery was created, as the recent events list shows when an event +arrived: how long ago, with the full UTC time on hover. + **Relations:** Belongs to Delivery. #### EventTotals, TargetTotals and EntrypointTotals diff --git a/internal/database/model_delivery.go b/internal/database/model_delivery.go index ffaba8a..5f22557 100644 --- a/internal/database/model_delivery.go +++ b/internal/database/model_delivery.go @@ -56,6 +56,10 @@ type Delivery struct { // the index. FinishedAt *time.Time `gorm:"index:idx_deliveries_status,priority:3" json:"finishedAt,omitempty"` + // Replay is set on a delivery created by the event log's Replay + // action, so the pages can tell it from the delivery it repeats. + Replay bool `gorm:"not null;default:false" json:"replay"` + // Relations. No model marshals the record it belongs to: // Event.Deliveries and Target.Deliveries lead back here, and the // JSON could loop. diff --git a/internal/handlers/delivery_replay.go b/internal/handlers/delivery_replay.go index be4c6d6..d3fc52f 100644 --- a/internal/handlers/delivery_replay.go +++ b/internal/handlers/delivery_replay.go @@ -283,6 +283,7 @@ func createReplayDelivery( EventID: event.ID, TargetID: target.ID, Status: database.DeliveryStatusPending, + Replay: true, } err := webhookDB.Transaction(func(tx *gorm.DB) error { diff --git a/internal/handlers/delivery_replay_test.go b/internal/handlers/delivery_replay_test.go index 332aa59..5f54af6 100644 --- a/internal/handlers/delivery_replay_test.go +++ b/internal/handlers/delivery_replay_test.go @@ -3,6 +3,7 @@ package handlers_test import ( "net/http" "net/http/httptest" + "strings" "testing" "github.com/stretchr/testify/assert" @@ -528,3 +529,48 @@ func TestHandleSourceLogs_RendersReplayControlAndBanner(t *testing.T) { assert.NotContains(t, unknown, "alert-success") assert.NotContains(t, unknown, "made-up") } + +// TestHandleDeliveryReplay_LabelsTheReplay proves a delivery created +// by Replay is labelled as a replay in the event's summary line in the +// event log, and in the list of the event's deliveries there and on +// the event's page, while the delivery it repeats is not. +func TestHandleDeliveryReplay_LabelsTheReplay(t *testing.T) { + t.Parallel() + + var ( + h *handlers.Handlers + sess *session.Session + db *database.Database + dbMgr *database.WebhookDBManager + ) + + app := newTestApp(t, &h, &sess, &db, &dbMgr) + app.RequireStart() + + t.Cleanup(app.RequireStop) + + wh := seedWebhook(t, db) + tgt := seedConfiguredTarget( + t, db, wh.ID, database.TargetTypeHTTP, + `{"url":"`+replayTargetURL+`"}`, + ) + + event, original := seedFailedDelivery(t, dbMgr, wh.ID, tgt.ID) + + w := postReplay(t, h, sess, wh.ID, original.ID) + require.Equal(t, http.StatusSeeOther, w.Code) + + eventLog := renderSourceLogsPage(t, h, sess, wh.ID) + + assert.Contains(t, eventLog, tgt.Name+": failed") + assert.Contains(t, eventLog, tgt.Name+" (replay): pending") + + w = serveEventPage(t, h, sess, wh.ID, event.ID) + require.Equal(t, http.StatusOK, w.Code) + + const label = `replay` + + for _, page := range []string{eventLog, w.Body.String()} { + assert.Equal(t, 1, strings.Count(page, label)) + } +} diff --git a/internal/handlers/delivery_result_view.go b/internal/handlers/delivery_result_view.go index 4b0e51f..f635b92 100644 --- a/internal/handlers/delivery_result_view.go +++ b/internal/handlers/delivery_result_view.go @@ -3,6 +3,7 @@ package handlers import ( "time" + "github.com/dustin/go-humanize" "sneak.berlin/go/webhooker/internal/delivery" ) @@ -47,6 +48,11 @@ type DeliveryResultView struct { AttemptNum int Success bool + // Ran is how long ago the attempt was recorded, and RanUTC the + // full timestamp the page shows on hover. + Ran string + RanUTC string + // StatusCode is 0 when the attempt never got a response, // which is why the page asks HasStatusCode rather than // printing the number. @@ -160,6 +166,8 @@ func (r *deliveryResultRow) view( return DeliveryResultView{ AttemptNum: r.AttemptNum, Success: r.Success, + Ran: humanize.Time(r.CreatedAt), + RanUTC: r.CreatedAt.UTC().Format(time.DateTime) + " UTC", StatusCode: r.StatusCode, Error: redactor.Redact(r.Error), DurationMS: r.Duration, diff --git a/internal/handlers/event_log_times_test.go b/internal/handlers/event_log_times_test.go new file mode 100644 index 0000000..7066c95 --- /dev/null +++ b/internal/handlers/event_log_times_test.go @@ -0,0 +1,52 @@ +package handlers_test + +import ( + "net/http" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "sneak.berlin/go/webhooker/internal/database" +) + +// TestEventLog_TimesCarryTheirZone proves that the event log shows +// when an event arrived, and that it and the event's page show when +// each delivery was created and each attempt recorded: each as how +// long ago, with the full UTC time on hover. +func TestEventLog_TimesCarryTheirZone(t *testing.T) { + t.Parallel() + + f := newRecentEventsFixture(t) + target := seedTarget(t, f.db, f.webhook.ID, database.TargetTypeHTTP) + + now := time.Now().UTC().Truncate(time.Second) + receivedAt := now.Add(-3 * time.Hour) + createdAt := now.Add(-90 * time.Minute) + ranAt := now.Add(-30 * time.Minute) + + event := f.event(t, contentTypeJSON, "{}", receivedAt) + dlv := f.deliveryQueuedAt( + t, event, target.ID, database.DeliveryStatusDelivered, createdAt, + ) + f.attempt(t, dlv, http.StatusOK, ranAt.Sub(createdAt)) + + w := serveEventPage(t, f.h, f.sess, f.webhook.ID, event.ID) + require.Equal(t, http.StatusOK, w.Code) + + eventPage := w.Body.String() + eventLog := renderSourceLogsPage(t, f.h, f.sess, f.webhook.ID) + + received := receivedAt.Format(time.DateTime) + assert.Contains(t, eventLog, `title="`+received+` UTC">3 hours ago`) + assert.NotContains(t, eventLog, received+"", + "an event's time must not be written without its zone") + assert.Contains(t, eventPage, received+" UTC") + + for _, page := range []string{eventLog, eventPage} { + assert.Contains(t, page, `title="`+createdAt.Format(time.DateTime)+ + ` UTC">created 1 hour ago`) + assert.Contains(t, page, `title="`+ranAt.Format(time.DateTime)+ + ` UTC">30 minutes ago`) + } +} diff --git a/internal/handlers/event_log_view.go b/internal/handlers/event_log_view.go index 3079493..4a3446e 100644 --- a/internal/handlers/event_log_view.go +++ b/internal/handlers/event_log_view.go @@ -3,6 +3,8 @@ package handlers import ( "time" "unicode/utf8" + + "github.com/dustin/go-humanize" ) // eventLogColumns is the event log's projection. The casts to @@ -28,10 +30,14 @@ const eventColumns = "id, created_at, method, content_type, " + // DeliveryView and TargetView. type EventLogView struct { ID string - CreatedAt time.Time Method string ContentType string + // Received is how long ago the event arrived, and ReceivedUTC + // the full timestamp. + Received string + ReceivedUTC string + Body BodyView // ResubmittedFromID names the event this one was copied @@ -77,9 +83,10 @@ func (r *eventLogRow) view(webhookID string) EventLogView { return EventLogView{ ID: r.ID, - CreatedAt: r.CreatedAt, Method: r.Method, ContentType: r.ContentType, + Received: humanize.Time(r.CreatedAt), + ReceivedUTC: r.CreatedAt.UTC().Format(time.DateTime) + " UTC", Body: newBodyView( "/hook/"+webhookID+"/events/"+r.ID, r.Body, r.BodyBytes, ), diff --git a/internal/handlers/source_management.go b/internal/handlers/source_management.go index 01dcb50..06a1465 100644 --- a/internal/handlers/source_management.go +++ b/internal/handlers/source_management.go @@ -11,6 +11,7 @@ import ( "strings" "time" + "github.com/dustin/go-humanize" "github.com/go-chi/chi" "github.com/google/uuid" "gorm.io/gorm" @@ -95,6 +96,14 @@ type DeliveryView struct { Status database.DeliveryStatus Target delivery.TargetView + // Replay is set on a delivery the Replay action created. + Replay bool + + // Created is how long ago the delivery was created, and + // CreatedUTC the full timestamp the page shows on hover. + Created string + CreatedUTC string + // Results is this delivery's attempts in attempt order, // bounded by maxRenderedAttempts. Without them a failure // renders as the status word alone and says nothing about @@ -1430,6 +1439,7 @@ func (h *Handlers) newDeliveryViews( for i := range deliveries { target := targetMap[deliveries[i].TargetID] rows := attempts[deliveries[i].ID] + created := deliveries[i].CreatedAt results, omitted := renderedAttempts( rows, target.Redactor, @@ -1439,6 +1449,9 @@ func (h *Handlers) newDeliveryViews( ID: deliveries[i].ID, Status: deliveries[i].Status, Target: target.View, + Replay: deliveries[i].Replay, + Created: humanize.Time(created), + CreatedUTC: created.UTC().Format(time.DateTime) + " UTC", Results: results, AttemptCount: len(rows), AttemptsOmitted: omitted, diff --git a/internal/handlers/target_list.go b/internal/handlers/target_list.go index 9333b2e..f6a3cad 100644 --- a/internal/handlers/target_list.go +++ b/internal/handlers/target_list.go @@ -88,8 +88,7 @@ func (h *Handlers) deliveryPausedView( } // newPausedView is a PausedView of deliveries paused until the given -// time. A time not on the current UTC day is written with its date, as -// the event log writes its times. +// time. A time not on the current UTC day is written with its date. func newPausedView(until time.Time) *PausedView { until = until.UTC() diff --git a/templates/delivery_attempts.html b/templates/delivery_attempts.html index 59d3b72..835efd0 100644 --- a/templates/delivery_attempts.html +++ b/templates/delivery_attempts.html @@ -9,6 +9,7 @@
Attempt {{.AttemptNum}} + {{.Ran}} {{if not .Success}}failure{{else if eq $.Target.Type "database"}}archived{{else if eq $.Target.Type "log"}}written to the log{{else}}success{{end}} {{/* A database or log target sends no HTTP request, so its attempts have no status code. */}} {{if not (eq $.Target.Type "database" "log")}} diff --git a/templates/event_detail.html b/templates/event_detail.html index 14241b1..07b0377 100644 --- a/templates/event_detail.html +++ b/templates/event_detail.html @@ -21,7 +21,7 @@
Received
-
{{.CreatedAt.UTC.Format "2006-01-02 15:04:05"}} UTC
+
{{.ReceivedUTC}}
Method
@@ -67,9 +67,13 @@ {{range .Deliveries}}
- {{.Target.DisplayName}} + + {{.Target.DisplayName}} + {{if .Replay}}replay{{end}} + {{with .Paused}}waiting: target paused after repeated failures, next try no earlier than {{.Until}} ({{.Relative}}){{else}}{{.Status}}{{end}} + created {{.Created}} {{.AttemptCount}} attempt{{if ne .AttemptCount 1}}s{{end}}
diff --git a/templates/source_logs.html b/templates/source_logs.html index d18ae87..4422778 100644 --- a/templates/source_logs.html +++ b/templates/source_logs.html @@ -32,10 +32,10 @@ {{range .Deliveries}} - {{.Target.DisplayName}}: {{if .Paused}}waiting{{else}}{{.Status}}{{end}} + {{.Target.DisplayName}}{{if .Replay}} (replay){{end}}: {{if .Paused}}waiting{{else}}{{.Status}}{{end}} {{end}} - {{.CreatedAt.Format "2006-01-02 15:04:05"}} + {{.Received}} @@ -67,9 +67,11 @@ {{.Target.DisplayName}} + {{if .Replay}}replay{{end}} {{with .Paused}}waiting: target paused after repeated failures, next try no earlier than {{.Until}} ({{.Relative}}){{else}}{{.Status}}{{end}} + created {{.Created}} {{.AttemptCount}} attempt{{if ne .AttemptCount 1}}s{{end}}