diff --git a/internal/handlers/event_log_view.go b/internal/handlers/event_log_view.go new file mode 100644 index 0000000..8d5837b --- /dev/null +++ b/internal/handlers/event_log_view.go @@ -0,0 +1,120 @@ +package handlers + +import ( + "time" + "unicode/utf8" +) + +// maxRenderedBodyBytes caps how many bytes of a stored event +// body reach the event log page. Bodies come from the +// unauthenticated receiver under the 1 MB ingest cap and +// renderTemplate buffers a whole page before writing it, so +// an uncapped page of paginationPerPage events is tens of +// megabytes of resident memory per concurrent viewer. +const maxRenderedBodyBytes = 8192 + +// eventLogColumns is the event log's projection. The casts to +// blob are load-bearing: they make substr and length count +// bytes rather than characters, so the cap bounds the page in +// bytes whatever the payload's encoding. Cutting in SQLite +// rather than in Go is the point of the projection — an +// oversized body never becomes a Go string at all. +const eventLogColumns = "id, created_at, method, content_type, " + + "substr(cast(body as blob), 1, ?) AS body, " + + "length(cast(body as blob)) AS body_bytes" + +// EventLogView is the display-safe projection of an event for +// the event log page, alongside DeliveryView and TargetView. +// It carries a capped body plus the true stored size, so the +// page can mark a body as truncated without ever holding the +// whole thing. +type EventLogView struct { + ID string + CreatedAt time.Time + Method string + ContentType string + + // Body holds at most maxRenderedBodyBytes bytes of the + // stored body. + Body string + + // BodyBytes is the true size of the stored body. + BodyBytes int64 + + // BodyTruncated reports that the stored body was larger + // than the cap, so the page owes the reader a marker. + BodyTruncated bool + + Deliveries []DeliveryView +} + +// BodyShownBytes is how many body bytes the page is actually +// rendering, which the truncation marker reports beside the +// true size. +func (v EventLogView) BodyShownBytes() int { + return len(v.Body) +} + +// eventLogRow is one row of the event log projection. Its +// body column arrives already cut to the cap by SQLite, with +// the true size beside it. +type eventLogRow struct { + ID string + CreatedAt time.Time + Method string + ContentType string + Body []byte + BodyBytes int64 +} + +// view projects a loaded row for rendering. +func (r *eventLogRow) view() EventLogView { + body := r.Body + truncated := r.BodyBytes > int64(len(body)) + + // Only a cut body can have been left mid-sequence by + // this query. A whole body is passed through exactly as + // stored, however malformed. + if truncated { + body = trimPartialRune(body) + } + + return EventLogView{ + ID: r.ID, + CreatedAt: r.CreatedAt, + Method: r.Method, + ContentType: r.ContentType, + Body: string(body), + BodyBytes: r.BodyBytes, + BodyTruncated: truncated, + } +} + +// trimPartialRune drops a trailing UTF-8 sequence that the +// byte-wise cut left incomplete, so a multi-byte rune severed +// at the cap does not surface as a mojibake tail. +// +// Bytes that are merely invalid UTF-8 are left exactly as +// stored: this service receives binary payloads, and rewriting +// them would misreport what was delivered. The distinction is +// utf8.FullRune's — it reports a complete sequence for an +// invalid encoding too, since that decodes to a width-1 error +// rune, so only a valid prefix still waiting for its +// continuation bytes is removed. A tail with no rune start in +// its last utf8.UTFMax bytes cannot be an incomplete sequence +// either, and is likewise left alone. +func trimPartialRune(b []byte) []byte { + for i := len(b) - 1; i >= 0 && len(b)-i <= utf8.UTFMax; i-- { + if !utf8.RuneStart(b[i]) { + continue + } + + if utf8.FullRune(b[i:]) { + return b + } + + return b[:i] + } + + return b +} diff --git a/internal/handlers/event_log_view_test.go b/internal/handlers/event_log_view_test.go new file mode 100644 index 0000000..7ffd2fb --- /dev/null +++ b/internal/handlers/event_log_view_test.go @@ -0,0 +1,258 @@ +package handlers_test + +import ( + "net/http" + "net/http/httptest" + "strconv" + "strings" + "testing" + "unicode/utf8" + + "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/handlers" + "sneak.berlin/go/webhooker/internal/session" +) + +// bodyCap is the number of body bytes the event log page is +// allowed to render for one event. +const bodyCap = handlers.MaxRenderedBodyBytesForTest + +// snowman is a three-byte rune, so a body of them straddles the +// byte-wise cut: bodyCap is not a multiple of three. +const snowman = "☃" + +// seedEventWithBody records one event with the given body in the +// webhook's own database. +func seedEventWithBody( + t *testing.T, + dbMgr *database.WebhookDBManager, + webhookID string, + body string, +) { + t.Helper() + + webhookDB, err := dbMgr.GetDB(webhookID) + require.NoError(t, err) + + event := &database.Event{ + WebhookID: webhookID, + Method: http.MethodPost, + Body: body, + ContentType: "application/octet-stream", + } + + require.NoError(t, webhookDB.Omit( + clause.Associations, + ).Create(event).Error) +} + +// seedAndProject stores one body and returns the projection the +// event log page would be handed for it. +func seedAndProject( + t *testing.T, + body string, +) handlers.EventLogView { + 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) + seedEventWithBody(t, dbMgr, wh.ID, body) + + views := h.LoadEventLogViewsForTest( + httptest.NewRecorder(), *wh, 1, + ) + require.Len(t, views, 1) + + return views[0] +} + +// TestHandleSourceLogs_BoundsOversizeBody proves the rendered +// page is bounded by the cap rather than by the stored payload: +// the body here is 64 times the cap, and the ingest path would +// accept twice as much again. +func TestHandleSourceLogs_BoundsOversizeBody(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) + + const ( + sentinel = "TAIL-SENTINEL-1f4a9c" + storedBytes = 512 * 1024 + ) + + wh := seedWebhook(t, db) + seedEventWithBody( + t, dbMgr, wh.ID, + strings.Repeat("A", storedBytes-len(sentinel))+sentinel, + ) + + page := renderSourceLogsPage(t, h, sess, wh.ID) + + // Nothing past the cap reaches the page, and the whole page + // stays far below the stored body it is reporting on. + assert.NotContains(t, page, sentinel) + assert.Less(t, len(page), 4*bodyCap) + + // The marker states the true stored size, not the cut one. + assert.Contains( + t, page, + "showing "+strconv.Itoa(bodyCap)+ + " of "+strconv.Itoa(storedBytes)+" bytes", + ) +} + +// TestHandleSourceLogs_SmallBodyRendersWhole guards the other +// side of the cap: a body under it is shown in full and carries +// no truncation marker. +func TestHandleSourceLogs_SmallBodyRendersWhole(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) + seedEventWithBody(t, dbMgr, wh.ID, `{"kept":"whole"}`) + + page := renderSourceLogsPage(t, h, sess, wh.ID) + + assert.Contains(t, page, ""kept"") + assert.NotContains(t, page, "Body truncated for display") +} + +// TestEventLogView_CutMidRune proves a multi-byte rune severed +// by the byte-wise cut is dropped rather than surfaced as a +// mojibake tail. +func TestEventLogView_CutMidRune(t *testing.T) { + t.Parallel() + + body := strings.Repeat(snowman, 4096) + view := seedAndProject(t, body) + + // bodyCap bytes hold bodyCap/3 whole snowmen and two bytes + // of the next one; those two are dropped. + whole := bodyCap / len(snowman) + + assert.True(t, view.BodyTruncated) + assert.Equal(t, int64(len(body)), view.BodyBytes) + assert.Equal(t, strings.Repeat(snowman, whole), view.Body) + assert.True(t, utf8.ValidString(view.Body)) + assert.LessOrEqual(t, len(view.Body), bodyCap) +} + +// TestEventLogView_BinaryBodyLeftAsStored proves a binary +// payload is passed through byte for byte. Its tail is invalid +// UTF-8 however the cut falls, so repairing it would misreport +// what the sender delivered. +func TestEventLogView_BinaryBodyLeftAsStored(t *testing.T) { + t.Parallel() + + raw := make([]byte, bodyCap+808) + for i := range raw { + // 0x80..0xBF: continuation bytes, never a rune start. + raw[i] = 0x80 | byte(i%0x40) + } + + view := seedAndProject(t, string(raw)) + + assert.True(t, view.BodyTruncated) + assert.Equal(t, int64(len(raw)), view.BodyBytes) + assert.Equal(t, string(raw[:bodyCap]), view.Body) + assert.False(t, utf8.ValidString(view.Body)) +} + +// TestTrimPartialRune covers the distinction the cut repair +// turns on: an incomplete but valid sequence is dropped, while +// bytes that are merely invalid UTF-8 are left alone. +func TestTrimPartialRune(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + in []byte + want []byte + }{{ + name: "complete ascii", + in: []byte("abc"), + want: []byte("abc"), + }, { + name: "complete multibyte", + in: []byte("ab" + snowman), + want: []byte("ab" + snowman), + }, { + name: "two byte rune cut", + in: []byte{'a', 0xC3}, + want: []byte{'a'}, + }, { + name: "three byte rune cut after one", + in: []byte{'a', 0xE2}, + want: []byte{'a'}, + }, { + name: "three byte rune cut after two", + in: []byte{'a', 0xE2, 0x98}, + want: []byte{'a'}, + }, { + name: "four byte rune cut", + in: []byte{'a', 0xF0, 0x9F, 0x92}, // U+1F4A9 cut + want: []byte{'a'}, + }, { + name: "invalid start byte kept", + in: []byte{'a', 0xFF}, + want: []byte{'a', 0xFF}, + }, { + name: "orphan continuation bytes kept", + in: []byte{0x80, 0x81, 0x82, 0x83, 0x84}, + want: []byte{0x80, 0x81, 0x82, 0x83, 0x84}, + }, { + name: "truncated sequence followed by junk kept", + in: []byte{0xE2, 0x98, 0xFF}, + want: []byte{0xE2, 0x98, 0xFF}, + }, { + name: "empty", + in: []byte{}, + want: []byte{}, + }} + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + assert.Equal( + t, tc.want, + handlers.TrimPartialRuneForTest(tc.in), + ) + }) + } +} diff --git a/internal/handlers/export_test.go b/internal/handlers/export_test.go index ac9fee3..78a6a59 100644 --- a/internal/handlers/export_test.go +++ b/internal/handlers/export_test.go @@ -3,8 +3,35 @@ package handlers import ( "html/template" "net/http" + + "sneak.berlin/go/webhooker/internal/database" ) +// MaxRenderedBodyBytesForTest exposes the event log's body cap +// to the handlers_test package. +const MaxRenderedBodyBytesForTest = maxRenderedBodyBytes + +// TrimPartialRuneForTest exposes trimPartialRune for use in the +// handlers_test package. +func TrimPartialRuneForTest(b []byte) []byte { + return trimPartialRune(b) +} + +// LoadEventLogViewsForTest exposes loadEventsWithDeliveries for +// use in the handlers_test package. Assertions on the projected +// body need the bytes as loaded: html/template rewrites invalid +// UTF-8 on the way out, so the rendered page cannot show whether +// a binary body survived the projection intact. +func (s *Handlers) LoadEventLogViewsForTest( + w http.ResponseWriter, + webhook database.Webhook, + page int, +) []EventLogView { + views, _ := s.loadEventsWithDeliveries(w, webhook, nil, page) + + return views +} + // AddTemplateForTest registers a template under a page name so that // the handlers_test package can drive the render path with a // template of its own. diff --git a/internal/handlers/handlers.go b/internal/handlers/handlers.go index e26d788..79403a6 100644 --- a/internal/handlers/handlers.go +++ b/internal/handlers/handlers.go @@ -229,8 +229,10 @@ func (s *Handlers) renderTemplate( // the response only once rendering has fully succeeded. Executing // straight into the ResponseWriter commits a partial body and a 200 // status before a mid-render error can be reported, leaving no way -// to serve a 500. These pages are small, so holding one in memory is -// the right trade. +// to serve a 500. Buffering makes a page's rendered size resident +// memory per concurrent viewer, so every page owes it a bound: the +// event log caps each stored body at maxRenderedBodyBytes for exactly +// this reason. func (s *Handlers) executeTemplate( w http.ResponseWriter, tmpl *template.Template, diff --git a/internal/handlers/source_management.go b/internal/handlers/source_management.go index 3b55e71..b538bcd 100644 --- a/internal/handlers/source_management.go +++ b/internal/handlers/source_management.go @@ -92,13 +92,6 @@ func parseRetentionDays(raw string, fallback int) (int, error) { return v, nil } -// EventWithDeliveries holds an event and its deliveries. -type EventWithDeliveries struct { - database.Event - - Deliveries []DeliveryView -} - // DeliveryView is the display-safe projection of a delivery // for the event log page. Its target is a TargetView, so the // stored configuration blob — which holds the target's @@ -815,16 +808,18 @@ func (h *Handlers) parsePage(r *http.Request) int { } // loadEventsWithDeliveries loads paginated events and their -// deliveries from the per-webhook database. +// deliveries from the per-webhook database. Events come back +// as capped projections rather than database.Event rows: see +// eventLogColumns for why the cut happens in SQL. func (h *Handlers) loadEventsWithDeliveries( w http.ResponseWriter, webhook database.Webhook, targetMap map[string]delivery.TargetView, page int, -) ([]EventWithDeliveries, int64) { +) ([]EventLogView, int64) { var totalEvents int64 - var result []EventWithDeliveries + var result []EventLogView if !h.dbMgr.DBExists(webhook.ID) { return result, totalEvents @@ -845,23 +840,25 @@ func (h *Handlers) loadEventsWithDeliveries( offset := (page - 1) * paginationPerPage - var events []database.Event + var rows []eventLogRow - webhookDB.Where( + webhookDB.Model(&database.Event{}).Select( + eventLogColumns, maxRenderedBodyBytes, + ).Where( "webhook_id = ?", webhook.ID, ).Order("created_at DESC").Offset(offset).Limit( paginationPerPage, - ).Find(&events) + ).Find(&rows) - result = make([]EventWithDeliveries, len(events)) + result = make([]EventLogView, len(rows)) - for i := range events { - result[i].Event = events[i] + for i := range rows { + result[i] = rows[i].view() var deliveries []database.Delivery webhookDB.Where( - "event_id = ?", events[i].ID, + "event_id = ?", rows[i].ID, ).Find(&deliveries) result[i].Deliveries = newDeliveryViews( diff --git a/templates/source_logs.html b/templates/source_logs.html index 2217466..e523712 100644 --- a/templates/source_logs.html +++ b/templates/source_logs.html @@ -37,6 +37,9 @@
{{.Body}}
+ {{if .BodyTruncated}}
+ Body truncated for display: showing {{.BodyShownBytes}} of {{.BodyBytes}} bytes. The stored body is unchanged.
+ {{end}}