From 51186b347b4e17b6125adb28e2464e3363acdbc4 Mon Sep 17 00:00:00 2001 From: clawbot <35+clawbot@noreply.example.org> Date: Tue, 29 Sep 2026 10:24:27 +0000 Subject: [PATCH] Show 50 recent events with size, processing time and status (closes #347) The recent events list on a webhook's page now shows the 50 newest events, each with its time relative to now (the full UTC timestamp on hover), its body size, its processing time and, when the webhook has exactly one HTTP target, that target's last HTTP status, colour-coded. Resubmitted copies are marked, as in the event log. Processing time is how long the event's slowest delivery took, from being queued to its last recorded attempt. It is read from the existing delivery and attempt timestamps, so nothing new is recorded. The body's size is read in SQL, never the body. Deliveries and attempts load in one batched query each, reusing the event log's attempt loader. Model: opus-5-5 --- go.mod | 2 +- internal/handlers/delivery_result_view.go | 8 +- internal/handlers/handlers.go | 2 +- internal/handlers/recent_events.go | 248 ++++++++++++++++++ internal/handlers/recent_events_test.go | 295 ++++++++++++++++++++++ internal/handlers/source_management.go | 17 +- templates/source_detail.html | 20 +- 7 files changed, 579 insertions(+), 13 deletions(-) create mode 100644 internal/handlers/recent_events.go create mode 100644 internal/handlers/recent_events_test.go diff --git a/go.mod b/go.mod index 3fbd1d2..ba81406 100644 --- a/go.mod +++ b/go.mod @@ -4,6 +4,7 @@ go 1.26.1 require ( github.com/99designs/basicauth-go v0.0.0-20230316000542-bf6f9cbbf0f8 + github.com/dustin/go-humanize v1.0.1 github.com/getsentry/sentry-go v0.25.0 github.com/go-chi/chi v1.5.5 github.com/go-chi/cors v1.2.1 @@ -29,7 +30,6 @@ require ( github.com/beorn7/perks v1.0.1 // indirect github.com/cespare/xxhash/v2 v2.2.0 // indirect github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc // indirect - github.com/dustin/go-humanize v1.0.1 // indirect github.com/gorilla/securecookie v1.1.2 // indirect github.com/jinzhu/inflection v1.0.0 // indirect github.com/jinzhu/now v1.1.5 // indirect diff --git a/internal/handlers/delivery_result_view.go b/internal/handlers/delivery_result_view.go index e3bb27b..c91bcd2 100644 --- a/internal/handlers/delivery_result_view.go +++ b/internal/handlers/delivery_result_view.go @@ -1,6 +1,8 @@ package handlers import ( + "time" + "sneak.berlin/go/webhooker/internal/delivery" ) @@ -25,7 +27,7 @@ const maxRenderedResponseBytes = 4096 // cut, so an oversized stored response never becomes a Go // string at all. const deliveryResultColumns = "delivery_id, attempt_num, success, " + - "status_code, error, duration, " + + "status_code, error, duration, created_at, " + "substr(cast(response_body as blob), 1, ?) AS response_body, " + "length(cast(response_body as blob)) AS response_bytes" @@ -106,6 +108,10 @@ type deliveryResultRow struct { Duration int64 ResponseBody []byte ResponseBytes int64 + + // CreatedAt is when the attempt's result was recorded, which + // is when the attempt finished. + CreatedAt time.Time } // view projects a loaded row for rendering, stripping the diff --git a/internal/handlers/handlers.go b/internal/handlers/handlers.go index 349771e..ad3bcd5 100644 --- a/internal/handlers/handlers.go +++ b/internal/handlers/handlers.go @@ -28,7 +28,7 @@ const ( // maxBodyShift is the bit shift for 1 MB body limit. maxBodyShift = 20 // recentEventLimit is the number of recent events to show. - recentEventLimit = 20 + recentEventLimit = 50 // paginationPerPage is the number of items per page. paginationPerPage = 25 diff --git a/internal/handlers/recent_events.go b/internal/handlers/recent_events.go new file mode 100644 index 0000000..0f7271b --- /dev/null +++ b/internal/handlers/recent_events.go @@ -0,0 +1,248 @@ +package handlers + +import ( + "net/http" + "strconv" + "time" + + "github.com/dustin/go-humanize" + "gorm.io/gorm" + "sneak.berlin/go/webhooker/internal/database" +) + +// recentEventColumns is the recent events list's projection. It +// reads the body's size and never the body itself, for the reason +// maxRenderedBodyBytes gives; the cast to blob makes length count +// bytes rather than characters. +const recentEventColumns = "id, created_at, method, content_type, " + + "resubmitted_from_id, length(cast(body as blob)) AS body_bytes" + +// RecentEventView is one row of the recent events list on a +// webhook's page. +type RecentEventView struct { + Method string + ContentType string + + // ResubmittedFromID names the event this one was copied from, + // empty for an event that arrived on the receiver. + ResubmittedFromID string + + // Received is how long ago the event arrived, and ReceivedUTC + // the full timestamp the page shows on hover. + Received string + ReceivedUTC string + + // Size is the size of the stored body. + Size string + + // ProcessingTime is how long the event's slowest delivery + // took; see processingTime. + ProcessingTime string + + // Status is what the webhook's HTTP target answered, and + // StatusClass its colour; see targetStatus. Both are empty + // unless the webhook has exactly one HTTP target. + Status string + StatusClass string +} + +// recentEventRow is one row of recentEventColumns. +type recentEventRow struct { + ID string + CreatedAt time.Time + Method string + ContentType string + ResubmittedFromID *string + BodyBytes uint64 +} + +// singleHTTPTargetID returns the ID of the webhook's HTTP target +// when it has exactly one, and "" when it has none or several. +func singleHTTPTargetID(targets []database.Target) string { + id := "" + count := 0 + + for i := range targets { + if targets[i].Type == database.TargetTypeHTTP { + id = targets[i].ID + count++ + } + } + + if count != 1 { + return "" + } + + return id +} + +// loadRecentEvents loads the webhook's recentEventLimit newest +// events for its page, newest first. statusTargetID is the +// webhook's only HTTP target, or "" when the list shows no status. +func (h *Handlers) loadRecentEvents( + webhookDB *gorm.DB, webhookID, statusTargetID string, +) ([]RecentEventView, error) { + var rows []recentEventRow + + err := webhookDB.Model(&database.Event{}). + Select(recentEventColumns). + Where("webhook_id = ?", webhookID). + Order("created_at DESC"). + Limit(recentEventLimit). + Find(&rows).Error + if err != nil { + return nil, err + } + + eventIDs := make([]string, len(rows)) + for i := range rows { + eventIDs[i] = rows[i].ID + } + + // Oldest first, so an event's last delivery to a target is its + // newest: a replay adds a delivery rather than changing the + // earlier one. + var deliveries []database.Delivery + + err = webhookDB. + Select("id, event_id, target_id, status, created_at"). + Where("event_id IN ?", eventIDs). + Order("created_at ASC"). + Find(&deliveries).Error + if err != nil { + return nil, err + } + + byEvent := make(map[string][]database.Delivery, len(rows)) + deliveryIDs := make([]string, len(deliveries)) + + for i := range deliveries { + eventID := deliveries[i].EventID + byEvent[eventID] = append(byEvent[eventID], deliveries[i]) + deliveryIDs[i] = deliveries[i].ID + } + + attempts, err := h.loadDeliveryResults(webhookDB, deliveryIDs) + if err != nil { + return nil, err + } + + views := make([]RecentEventView, len(rows)) + for i := range rows { + views[i] = rows[i].view( + byEvent[rows[i].ID], attempts, statusTargetID, + ) + } + + return views, nil +} + +// view projects a loaded row for rendering. deliveries is the +// event's deliveries, oldest first, and attempts their recorded +// attempts keyed by delivery ID. +func (r *recentEventRow) view( + deliveries []database.Delivery, + attempts map[string][]deliveryResultRow, + statusTargetID string, +) RecentEventView { + v := RecentEventView{ + Method: r.Method, + ContentType: r.ContentType, + Received: humanize.Time(r.CreatedAt), + ReceivedUTC: r.CreatedAt.UTC().Format(time.DateTime) + " UTC", + Size: humanize.Bytes(r.BodyBytes), + ProcessingTime: processingTime(deliveries, attempts), + } + + if r.ResubmittedFromID != nil { + v.ResubmittedFromID = *r.ResubmittedFromID + } + + if statusTargetID != "" { + v.Status, v.StatusClass = targetStatus( + deliveries, attempts, statusTargetID, + ) + } + + return v +} + +// processingTime is how long the event's slowest delivery took, +// from being queued to its last recorded attempt, time spent +// waiting between retries included. A delivery is queued when its +// event is received, or when an operator replays it, so a replay +// is timed from the replay rather than from the event's arrival. +// It is "in progress" while any delivery is pending or retrying, +// and empty for an event with no deliveries. +func processingTime( + deliveries []database.Delivery, + attempts map[string][]deliveryResultRow, +) string { + if len(deliveries) == 0 { + return "" + } + + var slowest time.Duration + + for i := range deliveries { + if !deliveries[i].Status.Terminal() { + return "in progress" + } + + tries := attempts[deliveries[i].ID] + if len(tries) == 0 { + continue + } + + last := tries[len(tries)-1].CreatedAt + slowest = max(slowest, last.Sub(deliveries[i].CreatedAt)) + } + + return slowest.Round(time.Millisecond).String() +} + +// targetStatus is what the target answered for the event, and the +// colour to show it in: the HTTP status code of the last attempt of +// the event's newest delivery to the target. Without a code it is +// "no response" when that attempt failed before a response +// arrived, the delivery's status ("pending") before any attempt, +// and "not sent" when the event has no delivery to the target. +func targetStatus( + deliveries []database.Delivery, + attempts map[string][]deliveryResultRow, + targetID string, +) (string, string) { + newest := -1 + + for i := range deliveries { + if deliveries[i].TargetID == targetID { + newest = i + } + } + + if newest < 0 { + return "not sent", "text-gray-400" + } + + tries := attempts[deliveries[newest].ID] + if len(tries) == 0 { + return string(deliveries[newest].Status), "text-gray-400" + } + + code := tries[len(tries)-1].StatusCode + + switch { + case code == 0: + return "no response", "text-red-600" + case code >= http.StatusInternalServerError: + return strconv.Itoa(code), "text-red-600" + case code >= http.StatusBadRequest: + return strconv.Itoa(code), "text-yellow-600" + case code >= http.StatusMultipleChoices: + return strconv.Itoa(code), "text-gray-500" + case code >= http.StatusOK: + return strconv.Itoa(code), "text-green-600" + default: + return strconv.Itoa(code), "text-gray-500" + } +} diff --git a/internal/handlers/recent_events_test.go b/internal/handlers/recent_events_test.go new file mode 100644 index 0000000..f8e440f --- /dev/null +++ b/internal/handlers/recent_events_test.go @@ -0,0 +1,295 @@ +package handlers_test + +import ( + "fmt" + "net/http" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "gorm.io/gorm" + "gorm.io/gorm/clause" + "sneak.berlin/go/webhooker/internal/database" + "sneak.berlin/go/webhooker/internal/handlers" + "sneak.berlin/go/webhooker/internal/session" +) + +// statusTitle marks the status column's cell in a recent events +// row; it is absent from the page when the column is not shown. +const statusTitle = `title="HTTP status from the HTTP target"` + +// recentEventsFixture is one started app and a webhook whose +// recent events list a test fills. +type recentEventsFixture struct { + h *handlers.Handlers + sess *session.Session + db *database.Database + webhook *database.Webhook + webhookDB *gorm.DB +} + +func newRecentEventsFixture(t *testing.T) *recentEventsFixture { + t.Helper() + + f := &recentEventsFixture{} + + var dbMgr *database.WebhookDBManager + + app := newTestApp(t, &f.h, &f.sess, &f.db, &dbMgr) + app.RequireStart() + + t.Cleanup(app.RequireStop) + + f.webhook = seedWebhook(t, f.db) + + webhookDB, err := dbMgr.GetDB(f.webhook.ID) + require.NoError(t, err) + + f.webhookDB = webhookDB + + return f +} + +func (f *recentEventsFixture) render(t *testing.T) string { + t.Helper() + + return renderSourceDetailPage(t, f.h, f.sess, f.webhook.ID) +} + +// event records an event received at receivedAt. +func (f *recentEventsFixture) event( + t *testing.T, contentType, body string, receivedAt time.Time, +) *database.Event { + t.Helper() + + event := &database.Event{ + WebhookID: f.webhook.ID, + Method: http.MethodPost, + Body: body, + ContentType: contentType, + } + event.CreatedAt = receivedAt + + require.NoError(t, f.webhookDB.Omit( + clause.Associations, + ).Create(event).Error) + + return event +} + +// delivery records a delivery of the event to the target, queued +// when the event was received. +func (f *recentEventsFixture) delivery( + t *testing.T, + event *database.Event, + targetID string, + status database.DeliveryStatus, +) *database.Delivery { + t.Helper() + + return f.deliveryQueuedAt( + t, event, targetID, status, event.CreatedAt, + ) +} + +// deliveryQueuedAt records a delivery of the event to the target, +// queued at queuedAt, as a replay is. +func (f *recentEventsFixture) deliveryQueuedAt( + t *testing.T, + event *database.Event, + targetID string, + status database.DeliveryStatus, + queuedAt time.Time, +) *database.Delivery { + t.Helper() + + dlv := &database.Delivery{ + EventID: event.ID, + TargetID: targetID, + Status: status, + } + dlv.CreatedAt = queuedAt + + require.NoError(t, f.webhookDB.Omit( + clause.Associations, + ).Create(dlv).Error) + + return dlv +} + +// attempt records one attempt of the delivery that finished took +// after the delivery was queued, with HTTP status code (0 for no +// response). +func (f *recentEventsFixture) attempt( + t *testing.T, dlv *database.Delivery, code int, took time.Duration, +) { + t.Helper() + + result := &database.DeliveryResult{ + DeliveryID: dlv.ID, + AttemptNum: 1, + StatusCode: code, + } + result.CreatedAt = dlv.CreatedAt.Add(took) + + require.NoError(t, f.webhookDB.Omit( + clause.Associations, + ).Create(result).Error) +} + +// statusCell is the status column's cell as the page renders it. +func statusCell(class, text string) string { + return `` + text + `` +} + +// TestHandleSourceDetail_ShowsFiftyNewestEvents proves the list +// holds the 50 newest events, newest first, and not one more. +func TestHandleSourceDetail_ShowsFiftyNewestEvents(t *testing.T) { + t.Parallel() + + f := newRecentEventsFixture(t) + base := time.Now().Add(-time.Hour) + + for i := range 51 { + f.event( + t, fmt.Sprintf("application/x-recent-%02d", i), "{}", + base.Add(time.Duration(i)*time.Second), + ) + } + + body := f.render(t) + + assert.Equal(t, 50, strings.Count(body, `title="Body size"`)) + assert.NotContains(t, body, "application/x-recent-00") + assert.Contains(t, body, "application/x-recent-01") + assert.Less( + t, + strings.Index(body, "application/x-recent-50"), + strings.Index(body, "application/x-recent-49"), + ) +} + +// TestHandleSourceDetail_RecentEventColumns proves a row shows its +// time relative with the UTC timestamp on hover, its body size, +// and its processing time once every delivery has finished. +func TestHandleSourceDetail_RecentEventColumns(t *testing.T) { + t.Parallel() + + f := newRecentEventsFixture(t) + logTarget := seedTarget(t, f.db, f.webhook.ID, database.TargetTypeLog) + + receivedAt := time.Now().Add(-210 * time.Second). + UTC().Truncate(time.Second) + + done := f.event( + t, contentTypeJSON, strings.Repeat("x", 2048), receivedAt, + ) + f.attempt( + t, + f.delivery(t, done, logTarget.ID, database.DeliveryStatusDelivered), + 0, 1500*time.Millisecond, + ) + + waiting := f.event(t, "text/plain", "{}", receivedAt) + f.delivery(t, waiting, logTarget.ID, database.DeliveryStatusPending) + + body := f.render(t) + + assert.Contains( + t, body, + `3 minutes ago`, + ) + assert.Contains(t, body, `2.0 kB`) + assert.Contains(t, body, ">1.5s") + assert.Contains(t, body, ">in progress") +} + +// TestHandleSourceDetail_StatusWithSingleHTTPTarget proves that a +// webhook with exactly one HTTP target shows, colour-coded, what +// that target answered for each event. The log target beside it +// does not count against "exactly one". +func TestHandleSourceDetail_StatusWithSingleHTTPTarget(t *testing.T) { + t.Parallel() + + f := newRecentEventsFixture(t) + target := seedTarget(t, f.db, f.webhook.ID, database.TargetTypeHTTP) + seedTarget(t, f.db, f.webhook.ID, database.TargetTypeLog) + + now := time.Now() + + for _, code := range []int{204, 302, 404, 503, 0} { + dlv := f.delivery( + t, f.event(t, contentTypeJSON, "{}", now), target.ID, + database.DeliveryStatusDelivered, + ) + f.attempt(t, dlv, code, time.Second) + } + + f.delivery( + t, f.event(t, contentTypeJSON, "{}", now), target.ID, + database.DeliveryStatusPending, + ) + f.event(t, contentTypeJSON, "{}", now) + + // A replay is a newer delivery, and its answer is the one shown. + replayed := f.event(t, contentTypeJSON, "{}", now) + f.attempt(t, f.delivery( + t, replayed, target.ID, database.DeliveryStatusFailed, + ), 502, time.Second) + f.attempt(t, f.deliveryQueuedAt( + t, replayed, target.ID, database.DeliveryStatusDelivered, + now.Add(time.Minute), + ), 200, time.Second) + + body := f.render(t) + + assert.Contains(t, body, statusCell("text-green-600", "204")) + assert.Contains(t, body, statusCell("text-gray-500", "302")) + assert.Contains(t, body, statusCell("text-yellow-600", "404")) + assert.Contains(t, body, statusCell("text-red-600", "503")) + assert.Contains(t, body, statusCell("text-red-600", "no response")) + assert.Contains(t, body, statusCell("text-gray-400", "pending")) + assert.Contains(t, body, statusCell("text-gray-400", "not sent")) + assert.Contains(t, body, statusCell("text-green-600", "200")) + assert.NotContains(t, body, ">502<") +} + +// TestHandleSourceDetail_NoStatusWithoutSingleHTTPTarget proves the +// status column is absent when the webhook has no HTTP target or +// more than one. +func TestHandleSourceDetail_NoStatusWithoutSingleHTTPTarget( + t *testing.T, +) { + t.Parallel() + + cases := map[string][]database.TargetType{ + "none": {database.TargetTypeLog}, + "several": {database.TargetTypeHTTP, database.TargetTypeHTTP}, + } + + for name, types := range cases { + t.Run(name, func(t *testing.T) { + t.Parallel() + + f := newRecentEventsFixture(t) + event := f.event(t, contentTypeJSON, "{}", time.Now()) + + for _, tt := range types { + target := seedTarget(t, f.db, f.webhook.ID, tt) + f.attempt(t, f.delivery( + t, event, target.ID, + database.DeliveryStatusDelivered, + ), 200, time.Second) + } + + body := f.render(t) + + assert.Contains(t, body, `title="Body size"`) + assert.NotContains(t, body, statusTitle) + }) + } +} diff --git a/internal/handlers/source_management.go b/internal/handlers/source_management.go index 4abb7fc..3f7135f 100644 --- a/internal/handlers/source_management.go +++ b/internal/handlers/source_management.go @@ -415,16 +415,21 @@ func (h *Handlers) renderSourceDetail( "webhook_id = ?", webhook.ID, ).Find(&targets) - var events []database.Event + var events []RecentEventView if h.dbMgr.DBExists(webhook.ID) { webhookDB, dbErr := h.dbMgr.GetDB(webhook.ID) if dbErr == nil { - webhookDB.Where( - "webhook_id = ?", webhook.ID, - ).Order("created_at DESC").Limit( - recentEventLimit, - ).Find(&events) + events, dbErr = h.loadRecentEvents( + webhookDB, webhook.ID, singleHTTPTargetID(targets), + ) + } + + if dbErr != nil { + h.log.Error( + "failed to load recent events", + "webhook_id", webhook.ID, "error", dbErr, + ) } } diff --git a/templates/source_detail.html b/templates/source_detail.html index 3b26967..a754719 100644 --- a/templates/source_detail.html +++ b/templates/source_detail.html @@ -187,12 +187,24 @@
{{range .Events}}
-
-
+
+
{{.Method}} - {{.ContentType}} + {{.ContentType}} + {{if .ResubmittedFromID}} + resubmitted copy + {{end}} +
+
+ {{.Size}} + {{if .ProcessingTime}} + {{.ProcessingTime}} + {{end}} + {{if .Status}} + {{.Status}} + {{end}} + {{.Received}}
- {{.CreatedAt.Format "2006-01-02 15:04:05 UTC"}}
{{else}} -- 2.54.0