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

README.md

@@ -3280,3 +3280,5 @@ MIT
 ## Author
 
 [@sneak](https://sneak.berlin)
+
+

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

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

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
 

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"
+	}
+}

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 `<span class="font-medium ` + class + `" ` + statusTitle +
+		`>` + text + `</span>`
+}
+
+// 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,
+		`<span title="`+receivedAt.Format(time.DateTime)+
+			` UTC">3 minutes ago</span>`,
+	)
+	assert.Contains(t, body, `<span title="Body size">2.0 kB</span>`)
+	assert.Contains(t, body, ">1.5s</span>")
+	assert.Contains(t, body, ">in progress</span>")
+}
+
+// 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)
+		})
+	}
+}

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,
+			)
 		}
 	}
 

templates/source_detail.html

@@ -187,12 +187,24 @@
         <div class="divide-y divide-gray-100">
             {{range .Events}}
             <div class="p-4">
-                <div class="flex items-center justify-between">
-                    <div class="flex items-center gap-3">
+                <div class="flex flex-wrap items-center justify-between gap-3">
+                    <div class="flex flex-wrap items-center gap-3">
                         <span class="badge-info">{{.Method}}</span>
-                        <span class="text-sm text-gray-500">{{.ContentType}}</span>
+                        <span class="text-sm text-gray-500 break-all">{{.ContentType}}</span>
+                        {{if .ResubmittedFromID}}
+                        <span class="text-xs text-gray-500" title="This event is a copy of {{.ResubmittedFromID}}">resubmitted copy</span>
+                        {{end}}
+                    </div>
+                    <div class="flex flex-wrap items-center gap-3 text-xs text-gray-400">
+                        <span title="Body size">{{.Size}}</span>
+                        {{if .ProcessingTime}}
+                        <span title="Processing time: how long the slowest delivery took, from being queued to its last attempt">{{.ProcessingTime}}</span>
+                        {{end}}
+                        {{if .Status}}
+                        <span class="font-medium {{.StatusClass}}" title="HTTP status from the HTTP target">{{.Status}}</span>
+                        {{end}}
+                        <span title="{{.ReceivedUTC}}">{{.Received}}</span>
                     </div>
-                    <span class="text-xs text-gray-400">{{.CreatedAt.Format "2006-01-02 15:04:05 UTC"}}</span>
                 </div>
             </div>
             {{else}}