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

@@ -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

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.

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 {

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 = `<span class="text-xs text-gray-500">replay</span>`
+
+	for _, page := range []string{eventLog, w.Body.String()} {
+		assert.Equal(t, 1, strings.Count(page, label))
+	}
+}

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,

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</span>`)
+	assert.NotContains(t, eventLog, received+"</span>",
+		"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</span>`)
+		assert.Contains(t, page, `title="`+ranAt.Format(time.DateTime)+
+			` UTC">30 minutes ago</span>`)
+	}
+}

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

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,

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()
 

templates/delivery_attempts.html

@@ -9,6 +9,7 @@
 <div class="rounded-md bg-white border border-gray-200 p-2">
     <div class="flex flex-wrap items-center gap-3 text-xs">
         <span class="text-gray-500">Attempt {{.AttemptNum}}</span>
+        <span class="text-gray-500" title="{{.RanUTC}}">{{.Ran}}</span>
         <span class="{{if .Success}}text-green-600{{else}}text-red-600{{end}}">{{if not .Success}}failure{{else if eq $.Target.Type "database"}}archived{{else if eq $.Target.Type "log"}}written to the log{{else}}success{{end}}</span>
         {{/* A database or log target sends no HTTP request, so its attempts have no status code. */}}
         {{if not (eq $.Target.Type "database" "log")}}

templates/event_detail.html

@@ -21,7 +21,7 @@
             </div>
             <div class="flex flex-wrap gap-2">
                 <dt class="w-32 flex-shrink-0 text-gray-500">Received</dt>
-                <dd class="text-gray-900">{{.CreatedAt.UTC.Format "2006-01-02 15:04:05"}} UTC</dd>
+                <dd class="text-gray-900">{{.ReceivedUTC}}</dd>
             </div>
             <div class="flex flex-wrap gap-2">
                 <dt class="w-32 flex-shrink-0 text-gray-500">Method</dt>
@@ -67,9 +67,13 @@
             {{range .Deliveries}}
             <div class="p-4">
                 <div class="flex flex-wrap items-center justify-between gap-3">
-                    <span class="text-sm text-gray-700">{{.Target.DisplayName}}</span>
+                    <span class="flex flex-wrap items-center gap-3">
+                        <span class="text-sm text-gray-700">{{.Target.DisplayName}}</span>
+                        {{if .Replay}}<span class="text-xs text-gray-500">replay</span>{{end}}
+                    </span>
                     <span class="flex flex-wrap items-center gap-3">
                         <span class="text-xs {{if eq .Status "delivered"}}text-green-600{{else if eq .Status "failed"}}text-red-600{{else if eq .Status "retrying"}}text-yellow-600{{else}}text-gray-400{{end}}">{{with .Paused}}waiting: target paused after repeated failures, next try no earlier than {{.Until}} ({{.Relative}}){{else}}{{.Status}}{{end}}</span>
+                        <span class="text-xs text-gray-400" title="{{.CreatedUTC}}">created {{.Created}}</span>
                         <span class="text-xs text-gray-400">{{.AttemptCount}} attempt{{if ne .AttemptCount 1}}s{{end}}</span>
                     </span>
                 </div>

templates/source_logs.html

@@ -32,10 +32,10 @@
                     <span class="flex flex-wrap items-center gap-4">
                         {{range .Deliveries}}
                         <span class="text-xs {{if eq .Status "delivered"}}text-green-600{{else if eq .Status "failed"}}text-red-600{{else if eq .Status "retrying"}}text-yellow-600{{else}}text-gray-400{{end}}">
-                            {{.Target.DisplayName}}: {{if .Paused}}waiting{{else}}{{.Status}}{{end}}
+                            {{.Target.DisplayName}}{{if .Replay}} (replay){{end}}: {{if .Paused}}waiting{{else}}{{.Status}}{{end}}
                         </span>
                         {{end}}
-                        <span class="text-xs text-gray-400">{{.CreatedAt.Format "2006-01-02 15:04:05"}}</span>
+                        <span class="text-xs text-gray-400" title="{{.ReceivedUTC}}">{{.Received}}</span>
                         <!-- The caret has no text to select, so a click on it toggles at once. -->
                         <svg class="w-4 h-4 text-gray-400 transition-transform" :class="caretClass" @click.stop="toggle" fill="none" stroke="currentColor" viewBox="0 0 24 24">
                             <path stroke-linecap="round" stroke-linejoin="round" stroke-width="2" d="M19 9l-7 7-7-7"/>
@@ -67,9 +67,11 @@
                                     <button type="button" class="btn-small flex-1 flex-wrap justify-between gap-2 text-left" @click="toggle">
                                         <span class="flex flex-wrap items-center gap-3">
                                             <span class="text-sm text-gray-700">{{.Target.DisplayName}}</span>
+                                            {{if .Replay}}<span class="text-xs text-gray-500">replay</span>{{end}}
                                             <span class="text-xs {{if eq .Status "delivered"}}text-green-600{{else if eq .Status "failed"}}text-red-600{{else if eq .Status "retrying"}}text-yellow-600{{else}}text-gray-400{{end}}">{{with .Paused}}waiting: target paused after repeated failures, next try no earlier than {{.Until}} ({{.Relative}}){{else}}{{.Status}}{{end}}</span>
                                         </span>
                                         <span class="flex flex-wrap items-center gap-3">
+                                            <span class="text-xs text-gray-400" title="{{.CreatedUTC}}">created {{.Created}}</span>
                                             <span class="text-xs text-gray-400">{{.AttemptCount}} attempt{{if ne .AttemptCount 1}}s{{end}}</span>
                                             <svg class="w-3 h-3 text-gray-400 transition-transform" :class="caretClass" fill="none" stroke="currentColor" viewBox="0 0 24 24">
                                                 <path stroke-linecap="round" stroke-linejoin="round" stroke-width="2" d="M19 9l-7 7-7-7"/>