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