Render delivery attempt detail in the event log (closes #202)

Expanding a delivery on the event log page now shows each recorded
attempt: attempt number, outcome, status code, duration, error and
response body. Previously a failure rendered as "target: failed" and
diagnosing it meant opening the per-webhook SQLite file by hand.

The response body is cut by SQLite via substr over a blob cast, the
same projection the event body uses, so an oversized stored response
never becomes a Go string. The page reports the cut with a marker.

Response bodies and errors are remote content, so both go through a
new delivery.Redactor that strips the target's own destination URL,
path, query and userinfo before rendering. Configured HTTP header
values are deliberately not redacted; they are as often routine as
secret, and replacing them would mangle ordinary responses. Target
configuration keeps reaching the template only as a TargetView.

internal/handlers/delivery_result_view.go

@@ -0,0 +1,126 @@
+package handlers
+
+import (
+	"sneak.berlin/go/webhooker/internal/delivery"
+)
+
+// maxRenderedResponseBytes caps how many bytes of one stored
+// delivery response body reach the event log page.
+//
+// It matches the cap the delivery engine applies when it
+// records a result, so nothing written by the current engine
+// is cut twice. The bound is enforced here anyway, and in
+// SQL: this page's memory profile must not depend on a
+// constant in another package staying where it is, and rows
+// predating that cap or restored from an archive are not
+// covered by it at all.
+const maxRenderedResponseBytes = 4096
+
+// deliveryResultColumns is the delivery attempt projection.
+// The casts to blob are load-bearing for the same reason they
+// are in eventLogColumns: they make substr and length count
+// bytes rather than characters, and they make SQLite do the
+// cut, so an oversized stored response never becomes a Go
+// string at all.
+const deliveryResultColumns = "delivery_id, attempt_num, success, " +
+	"status_code, error, duration, " +
+	"substr(cast(response_body as blob), 1, ?) AS response_body, " +
+	"length(cast(response_body as blob)) AS response_bytes"
+
+// DeliveryResultView is the display-safe projection of one
+// delivery attempt for the event log page. It carries a
+// capped response body plus the true stored size, so the page
+// can mark a response as truncated without holding the whole
+// thing.
+//
+// Both Error and ResponseBody have been through the target's
+// Redactor. The engine already masks the URL out of the
+// errors it stores, so for errors this is a second line
+// covering rows written before it did; for response bodies it
+// is the only line, and its reach is what
+// delivery.Redactor documents.
+type DeliveryResultView struct {
+	AttemptNum int
+	Success    bool
+
+	// StatusCode is 0 when the attempt never got a response,
+	// which is why the page asks HasStatusCode rather than
+	// printing the number.
+	StatusCode int
+
+	// Error is the stored failure message, redacted.
+	Error string
+
+	// DurationMS is how long the attempt took.
+	DurationMS int64
+
+	// ResponseBody holds at most maxRenderedResponseBytes
+	// bytes of the stored response, redacted. It is remote
+	// content and must only ever be rendered escaped.
+	ResponseBody string
+
+	// ResponseBytes is the true size of the stored response
+	// body, before the cut and before redaction.
+	ResponseBytes int64
+
+	// ResponseShownBytes is how much of that the page is
+	// showing. It is the size of the cut, taken before
+	// redaction, so the truncation marker reports what SQLite
+	// returned rather than how much the marker substitution
+	// then changed the length.
+	ResponseShownBytes int
+
+	// ResponseTruncated reports that the stored response was
+	// larger than the cap, so the page owes the reader a
+	// marker.
+	ResponseTruncated bool
+}
+
+// HasStatusCode reports whether the attempt got as far as an
+// HTTP response. A transport failure stores no status code,
+// and rendering that as "0" would read as a real status.
+func (v DeliveryResultView) HasStatusCode() bool {
+	return v.StatusCode != 0
+}
+
+// deliveryResultRow is one row of the delivery attempt
+// projection. Its response body arrives already cut to the
+// cap by SQLite, with the true size beside it.
+type deliveryResultRow struct {
+	DeliveryID    string
+	AttemptNum    int
+	Success       bool
+	StatusCode    int
+	Error         string
+	Duration      int64
+	ResponseBody  []byte
+	ResponseBytes int64
+}
+
+// view projects a loaded row for rendering, stripping the
+// target's own credential out of the two fields a remote peer
+// gets to influence.
+func (r *deliveryResultRow) view(
+	redactor delivery.Redactor,
+) DeliveryResultView {
+	body := r.ResponseBody
+	truncated := r.ResponseBytes > int64(len(body))
+
+	// Only a cut response can have been left mid-sequence by
+	// this query, exactly as with an event body.
+	if truncated {
+		body = trimPartialRune(body)
+	}
+
+	return DeliveryResultView{
+		AttemptNum:         r.AttemptNum,
+		Success:            r.Success,
+		StatusCode:         r.StatusCode,
+		Error:              redactor.Redact(r.Error),
+		DurationMS:         r.Duration,
+		ResponseBody:       redactor.Redact(string(body)),
+		ResponseBytes:      r.ResponseBytes,
+		ResponseShownBytes: len(body),
+		ResponseTruncated:  truncated,
+	}
+}

internal/handlers/delivery_result_view_test.go

@@ -0,0 +1,306 @@
+package handlers_test
+
+import (
+	"net/http"
+	"net/http/httptest"
+	"strconv"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"gorm.io/gorm/clause"
+	"sneak.berlin/go/webhooker/internal/database"
+	"sneak.berlin/go/webhooker/internal/delivery"
+	"sneak.berlin/go/webhooker/internal/handlers"
+	"sneak.berlin/go/webhooker/internal/session"
+)
+
+// responseCap is the number of response bytes the event log
+// page is allowed to render for one delivery attempt.
+const responseCap = handlers.MaxRenderedResponseBytesForTest
+
+// failedAttempt describes the failed delivery every test in
+// this file seeds. The values are distinctive so that finding
+// them in the rendered page cannot be a coincidence.
+const (
+	attemptStatusCode = 502
+	attemptDurationMS = 1234
+	attemptNumber     = 3
+	attemptError      = "upstream returned 502 Bad Gateway"
+)
+
+// seedFailedDelivery records an event, a failed delivery
+// against targetID, and one delivery result carrying the
+// given response body. It returns the delivery.
+func seedFailedDelivery(
+	t *testing.T,
+	dbMgr *database.WebhookDBManager,
+	webhookID, targetID, responseBody string,
+) *database.Delivery {
+	t.Helper()
+
+	webhookDB, err := dbMgr.GetDB(webhookID)
+	require.NoError(t, err)
+
+	event := &database.Event{
+		WebhookID:   webhookID,
+		Method:      http.MethodPost,
+		Body:        `{"test":true}`,
+		ContentType: "application/json",
+	}
+
+	require.NoError(t, webhookDB.Omit(
+		clause.Associations,
+	).Create(event).Error)
+
+	dlv := &database.Delivery{
+		EventID:  event.ID,
+		TargetID: targetID,
+		Status:   database.DeliveryStatusFailed,
+	}
+
+	require.NoError(t, webhookDB.Omit(
+		clause.Associations,
+	).Create(dlv).Error)
+
+	result := &database.DeliveryResult{
+		DeliveryID:   dlv.ID,
+		AttemptNum:   attemptNumber,
+		Success:      false,
+		StatusCode:   attemptStatusCode,
+		ResponseBody: responseBody,
+		Error:        attemptError,
+		Duration:     attemptDurationMS,
+	}
+
+	require.NoError(t, webhookDB.Omit(
+		clause.Associations,
+	).Create(result).Error)
+
+	return dlv
+}
+
+// seedFailureAndRender seeds a failed delivery against a
+// target of the given type and config, and returns the
+// rendered event log page.
+func seedFailureAndRender(
+	t *testing.T,
+	targetType database.TargetType,
+	config, responseBody string,
+) string {
+	t.Helper()
+
+	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, targetType, config,
+	)
+
+	seedFailedDelivery(t, dbMgr, wh.ID, tgt.ID, responseBody)
+
+	return renderSourceLogsPage(t, h, sess, wh.ID)
+}
+
+// TestHandleSourceLogs_RendersFailedAttempt is the regression
+// test for the reported gap: a failed delivery used to render
+// as the status word alone, so diagnosing it meant opening the
+// per-webhook SQLite file by hand.
+func TestHandleSourceLogs_RendersFailedAttempt(t *testing.T) {
+	t.Parallel()
+
+	body := seedFailureAndRender(
+		t,
+		database.TargetTypeHTTP,
+		`{"url":"https://example.com/hook/abc"}`,
+		"upstream exploded",
+	)
+
+	assert.Contains(
+		t, body, strconv.Itoa(attemptStatusCode),
+		"the attempt's status code must reach the page",
+	)
+	assert.Contains(
+		t, body, attemptError,
+		"the attempt's error must reach the page",
+	)
+	assert.Contains(
+		t, body, strconv.Itoa(attemptDurationMS),
+		"the attempt's duration must reach the page",
+	)
+	assert.Contains(
+		t, body, "Attempt "+strconv.Itoa(attemptNumber),
+		"the attempt number must reach the page",
+	)
+	assert.Contains(
+		t, body, "upstream exploded",
+		"the attempt's response body must reach the page",
+	)
+}
+
+// TestHandleSourceLogs_EscapesResponseBody proves the
+// response body is treated as the untrusted remote content it
+// is. The remote chooses these bytes and the page is rendered
+// inside the operator's authenticated origin, where the
+// application's own CSP allows inline script from 'self'.
+func TestHandleSourceLogs_EscapesResponseBody(t *testing.T) {
+	t.Parallel()
+
+	const payload = `<script>alert("xss")</script>`
+
+	body := seedFailureAndRender(
+		t,
+		database.TargetTypeHTTP,
+		`{"url":"https://example.com/hook/abc"}`,
+		payload,
+	)
+
+	assert.NotContains(t, body, payload)
+	assert.NotContains(t, body, "<script>alert")
+	assert.Contains(t, body, "alert")
+}
+
+// TestHandleSourceLogs_RedactsCredentialEchoedInResponse
+// covers the case that makes rendering a response body a
+// disclosure question at all: the remote echoes back the
+// credential the request carried, and the page would then put
+// it on the operator's screen.
+func TestHandleSourceLogs_RedactsCredentialEchoedInResponse(
+	t *testing.T,
+) {
+	t.Parallel()
+
+	body := seedFailureAndRender(
+		t,
+		database.TargetTypeSlack,
+		`{"webhookUrl":"`+slackWebhookURL+`"}`,
+		"no_service: "+slackWebhookURL,
+	)
+
+	assert.NotContains(t, body, slackSecretPath)
+	assert.NotContains(t, body, "T00000000")
+	assert.NotContains(t, body, "B00000000")
+	assert.Contains(t, body, delivery.RedactionMarker)
+
+	// The rest of the response is still shown, or the
+	// redaction would have cost the operator the diagnosis.
+	assert.Contains(t, body, "no_service")
+}
+
+// TestHandleSourceLogs_RedactsCredentialEchoedInError covers
+// the same disclosure through the error field. The delivery
+// engine masks the URL out of the errors it stores, so this
+// holds the read path to the rows written before it did.
+func TestHandleSourceLogs_RedactsCredentialEchoedInError(
+	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.TargetTypeSlack,
+		`{"webhookUrl":"`+slackWebhookURL+`"}`,
+	)
+
+	dlv := seedFailedDelivery(t, dbMgr, wh.ID, tgt.ID, "")
+
+	webhookDB, err := dbMgr.GetDB(wh.ID)
+	require.NoError(t, err)
+
+	// An unmasked transport error, exactly as Go's HTTP
+	// client renders one.
+	require.NoError(t, webhookDB.Model(
+		&database.DeliveryResult{},
+	).Where(
+		"delivery_id = ?", dlv.ID,
+	).Update(
+		"error",
+		`Post "`+slackWebhookURL+`": dial tcp: i/o timeout`,
+	).Error)
+
+	body := renderSourceLogsPage(t, h, sess, wh.ID)
+
+	assert.NotContains(t, body, slackSecretPath)
+	assert.Contains(t, body, delivery.RedactionMarker)
+	assert.Contains(t, body, "i/o timeout")
+}
+
+// TestHandleSourceLogs_BoundsOversizeResponse proves the
+// rendered page is bounded by the response cap rather than by
+// the stored response size. The cut happens in SQLite, so the
+// oversized value never becomes a Go string; this asserts the
+// observable consequence, that neither the page nor the
+// projection carries the tail.
+func TestHandleSourceLogs_BoundsOversizeResponse(t *testing.T) {
+	t.Parallel()
+
+	const tail = "QQRESPONSETAILQQ"
+
+	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.TargetTypeLog, "",
+	)
+
+	stored := strings.Repeat("A", responseCap*4) + tail
+	seedFailedDelivery(t, dbMgr, wh.ID, tgt.ID, stored)
+
+	views := h.LoadEventLogViewsForTest(
+		httptest.NewRecorder(), *wh, 1,
+	)
+	require.Len(t, views, 1)
+	require.Len(t, views[0].Deliveries, 1)
+	require.Len(t, views[0].Deliveries[0].Results, 1)
+
+	attempt := views[0].Deliveries[0].Results[0]
+
+	assert.LessOrEqual(
+		t, len(attempt.ResponseBody), responseCap,
+	)
+	assert.Equal(
+		t, int64(len(stored)), attempt.ResponseBytes,
+	)
+	assert.True(t, attempt.ResponseTruncated)
+
+	page := renderSourceLogsPage(t, h, sess, wh.ID)
+
+	assert.NotContains(t, page, tail)
+	assert.Contains(
+		t, page, "Response truncated for display",
+	)
+}

internal/handlers/export_test.go

@@ -19,6 +19,10 @@ func (s *Handlers) SetLogForTest(log *slog.Logger) {
 // to the handlers_test package.
 const MaxRenderedBodyBytesForTest = maxRenderedBodyBytes
 
+// MaxRenderedResponseBytesForTest exposes the event log's
+// delivery response cap to the handlers_test package.
+const MaxRenderedResponseBytesForTest = maxRenderedResponseBytes
+
 // DummyVerificationsForTest reports how many equivalent-cost
 // verifications were charged for usernames that do not exist. It
 // lets a test prove the anti-enumeration path ran without timing

internal/handlers/source_management.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/go-chi/chi"
 	"github.com/google/uuid"
+	"gorm.io/gorm"
 	"sneak.berlin/go/webhooker/internal/database"
 	"sneak.berlin/go/webhooker/internal/delivery"
 )
@@ -100,6 +101,22 @@ type DeliveryView struct {
 	ID     string
 	Status database.DeliveryStatus
 	Target delivery.TargetView
+
+	// Results is every recorded attempt at this delivery, in
+	// attempt order. Without it a failure renders as the
+	// status word alone and says nothing about why.
+	Results []DeliveryResultView
+}
+
+// eventLogTarget is what the event log needs to know about
+// one target: the display-safe view its template renders, and
+// the redactor that keeps that target's own credential out of
+// the text its remote peer chose. The two are kept together
+// so a caller cannot pick up one without the other, and apart
+// from TargetView so the secrets never reach a template.
+type eventLogTarget struct {
+	View     delivery.TargetView
+	Redactor delivery.Redactor
 }
 
 // HandleSourceList shows a list of user's webhooks.
@@ -794,26 +811,35 @@ func (h *Handlers) HandleSourceLogs() http.HandlerFunc {
 }
 
 // loadTargetMap loads targets into a map of display-safe
-// views keyed by target ID. The projection happens here so
-// that no caller can hand a raw target, configuration blob
-// and all, to a template.
+// views keyed by target ID, each paired with its redactor.
+// The projection happens here so that no caller can hand a
+// raw target, configuration blob and all, to a template: the
+// raw rows do not leave this function.
 func (h *Handlers) loadTargetMap(
 	webhookID string,
-) map[string]delivery.TargetView {
+) map[string]eventLogTarget {
 	var targets []database.Target
 
 	h.db.DB().Where(
 		"webhook_id = ?", webhookID,
 	).Find(&targets)
 
-	views := delivery.NewTargetViews(targets)
-
 	targetMap := make(
-		map[string]delivery.TargetView, len(views),
+		map[string]eventLogTarget, len(targets),
 	)
 
-	for _, v := range views {
-		targetMap[v.ID] = v
+	for i := range targets {
+		targetMap[targets[i].ID] = eventLogTarget{
+			Redactor: delivery.NewRedactor(&targets[i]),
+		}
+	}
+
+	// The views come from NewTargetViews rather than being
+	// rebuilt here, so the masking rules stay in one place.
+	for _, v := range delivery.NewTargetViews(targets) {
+		entry := targetMap[v.ID]
+		entry.View = v
+		targetMap[v.ID] = entry
 	}
 
 	return targetMap
@@ -840,7 +866,7 @@ func (h *Handlers) parsePage(r *http.Request) int {
 func (h *Handlers) loadEventsWithDeliveries(
 	w http.ResponseWriter,
 	webhook database.Webhook,
-	targetMap map[string]delivery.TargetView,
+	targetMap map[string]eventLogTarget,
 	page int,
 ) ([]EventLogView, int64) {
 	var totalEvents int64
@@ -877,37 +903,96 @@ func (h *Handlers) loadEventsWithDeliveries(
 	).Find(&rows)
 
 	result = make([]EventLogView, len(rows))
+	eventDeliveries := make([][]database.Delivery, len(rows))
+
+	var deliveryIDs []string
 
 	for i := range rows {
 		result[i] = rows[i].view()
 
-		var deliveries []database.Delivery
-
 		webhookDB.Where(
 			"event_id = ?", rows[i].ID,
-		).Find(&deliveries)
+		).Find(&eventDeliveries[i])
 
+		for j := range eventDeliveries[i] {
+			deliveryIDs = append(
+				deliveryIDs, eventDeliveries[i][j].ID,
+			)
+		}
+	}
+
+	attempts := h.loadDeliveryResults(webhookDB, deliveryIDs)
+
+	for i := range rows {
 		result[i].Deliveries = newDeliveryViews(
-			deliveries, targetMap,
+			eventDeliveries[i], targetMap, attempts,
 		)
 	}
 
 	return result, totalEvents
 }
 
+// loadDeliveryResults loads every recorded attempt for the
+// page's deliveries in one query, keyed by delivery ID.
+//
+// Each response body is cut by SQLite rather than in Go, for
+// the reason deliveryResultColumns gives. What the cut does
+// not bound is how many attempts a delivery has: that is the
+// target's MaxRetries, which the authenticated operator sets
+// — the same class of operator-chosen dimension as the number
+// of targets a webhook has, which this page already accepts.
+// No part of it is chosen by the unauthenticated sender.
+func (h *Handlers) loadDeliveryResults(
+	webhookDB *gorm.DB,
+	deliveryIDs []string,
+) map[string][]deliveryResultRow {
+	if len(deliveryIDs) == 0 {
+		return nil
+	}
+
+	var rows []deliveryResultRow
+
+	webhookDB.Model(&database.DeliveryResult{}).Select(
+		deliveryResultColumns, maxRenderedResponseBytes,
+	).Where(
+		"delivery_id IN ?", deliveryIDs,
+	).Order("attempt_num ASC").Find(&rows)
+
+	byDelivery := make(map[string][]deliveryResultRow)
+
+	for i := range rows {
+		byDelivery[rows[i].DeliveryID] = append(
+			byDelivery[rows[i].DeliveryID], rows[i],
+		)
+	}
+
+	return byDelivery
+}
+
 // newDeliveryViews projects deliveries for rendering,
-// resolving each one's target to its display-safe view.
+// resolving each one's target to its display-safe view and
+// each one's attempts through that target's redactor.
 func newDeliveryViews(
 	deliveries []database.Delivery,
-	targetMap map[string]delivery.TargetView,
+	targetMap map[string]eventLogTarget,
+	attempts map[string][]deliveryResultRow,
 ) []DeliveryView {
 	views := make([]DeliveryView, len(deliveries))
 
 	for i := range deliveries {
+		target := targetMap[deliveries[i].TargetID]
+		rows := attempts[deliveries[i].ID]
+
+		results := make([]DeliveryResultView, len(rows))
+		for j := range rows {
+			results[j] = rows[j].view(target.Redactor)
+		}
+
 		views[i] = DeliveryView{
-			ID:     deliveries[i].ID,
-			Status: deliveries[i].Status,
-			Target: targetMap[deliveries[i].TargetID],
+			ID:      deliveries[i].ID,
+			Status:  deliveries[i].Status,
+			Target:  target.View,
+			Results: results,
 		}
 	}