Milestone: next into main (#380)

Reviewed-on: #380

README.md

@@ -1325,11 +1325,9 @@ webhooker solves this by acting as a durable intermediary:
     deliberately left in a recoverable state rather than marked done — losing a
     delivery is the worse failure — so the pending sweep picks it up about
     fifteen minutes later, or the next restart does, and the target receives a
-    payload it already got. A send still in flight when the service stops is
+    payload it already got. webhooker adds no delivery identifier of its own to
-    left the same way: its attempt is not recorded, and the next start sends it
+    an outbound request, so **make your receiver idempotent** against whatever
-    again (see Shutdown). webhooker adds no delivery identifier of its own to an
+    the payload itself carries.
-    outbound request, so **make your receiver idempotent** against whatever the
-    payload itself carries.
 
 3. **Observability** — Full request/response logging for every webhook received
    and every delivery attempted. Prometheus metrics expose volume, latency, and
@@ -1770,7 +1768,7 @@ is what bounds it.
 #### DeliveryResult
 
 The result of a single delivery attempt. Every attempt (including retries) is
-individually logged, except one cut off by a stop (see Shutdown).
+individually logged for full observability.
 
 | Field           | Type    | Description                               |
 | --------------- | ------- | ----------------------------------------- |
@@ -2208,14 +2206,12 @@ This means:
   buffer rather than spawning more goroutines.
 - **Independent results** — each worker records its own delivery result in the
   per-webhook database without coordination.
-- **Graceful shutdown** — the stop hook cancels the workers' context, and each
+- **Graceful shutdown** — cancel the context, workers finish their current task
-  worker exits once its current task returns. Cancelling cuts off an `http` or
+  and exit. The stop hook waits for the pool via `lifecycle.WaitForShutdown`,
-  `slack` request still in flight; that attempt is not recorded, and the next
+  which bounds that wait by fx's stop timeout rather than blocking forever on a
-  start sends the delivery again (see Shutdown). The stop hook waits for the
+  wedged worker. On timeout it logs at `ERROR` and returns an error, and the
-  pool via `lifecycle.WaitForShutdown`, which bounds that wait by fx's stop
+  goroutines that did not finish are still running — an unclean shutdown is
-  timeout rather than blocking forever on a wedged worker. On timeout it logs at
+  reported rather than hidden.
-  `ERROR` and returns an error, and the goroutines that did not finish are still
-  running — an unclean shutdown is reported rather than hidden.
 
 **Recovery paths:**
 
@@ -3288,8 +3284,7 @@ stop-hook log:
 3. `server` — the HTTP drain, bounded by `server.ShutdownTimeout` (**3
    seconds**) and by what the hooks before it left, then a Sentry flush if
    `SENTRY_DSN` is set
-4. `delivery.Engine` — cuts off any `http` or `slack` request in flight, waits
+4. `delivery.Engine` — waits for its workers, then closes the archive databases
-   for its workers, then closes the archive databases
 5. `healthcheck`
 6. `WebhookDBManager`
 7. the database close
@@ -3300,12 +3295,6 @@ by the stop context, so a wedge there consumes the 5 seconds before the HTTP
 server hook is ever entered. The hooks after the server are microsecond-scale in
 normal operation.
 
-The delivery engine does not wait for a delivery request in flight: it cancels
-it. That attempt is not recorded and the delivery keeps its `pending` or
-`retrying` status, so startup recovery sends it again on the next start (see
-Recovery paths under Bounded Worker Pool). If the receiver already had it, it
-receives it twice: the at-least-once duplicate described under Rationale.
-
 The HTTP drain budget is deliberately **shorter** than the sequence budget. Were
 the two equal, a drain that used its whole budget would exhaust the sequence
 budget at the instant it finished, and every later hook — the delivery engine,

internal/delivery/delivery_totals_test.go

@@ -32,8 +32,9 @@ func targetTotals(
 
 // TestUpdateDeliveryStatus_FinishTimeAndTargetTotals pins what a status
 // write records for the webhook page's statistics: the time a delivery
-// finished, set only when it becomes delivered or failed, and one more
+// finished, set only when it becomes delivered or failed and stored in
-// on its target's delivered or failed total.
+// the same form as created_at, and one more on its target's delivered
+// or failed total.
 func TestUpdateDeliveryStatus_FinishTimeAndTargetTotals(t *testing.T) {
 	t.Parallel()
 
@@ -75,6 +76,16 @@ func TestUpdateDeliveryStatus_FinishTimeAndTargetTotals(t *testing.T) {
 			if tt.finished {
 				require.NotNil(t, stored.FinishedAt)
 				assert.False(t, stored.FinishedAt.Before(before))
+
+				var createdAt, finishedAt string
+
+				require.NoError(t, db.Raw(
+					`SELECT CAST(created_at AS TEXT),
+						CAST(finished_at AS TEXT)
+					FROM deliveries WHERE id = ?`, d.ID,
+				).Row().Scan(&createdAt, &finishedAt))
+				assertStoredTime(t, createdAt)
+				assertStoredTime(t, finishedAt)
 			} else {
 				assert.Nil(t, stored.FinishedAt)
 			}

internal/delivery/engine.go

@@ -1702,7 +1702,10 @@ func writeDeliveryStatus(
 		}).
 		Updates(map[string]any{
 			"status": status,
-			"finished_at": time.Now(),
+			// GORM's clock, the one that stamps created_at. A bare
+			// time.Now() carries a monotonic clock reading, which the
+			// driver would store as an " m=+…" suffix.
+			"finished_at": tx.NowFunc(),
 		})
 	if res.Error != nil || res.RowsAffected == 0 {
 		return res.Error
@@ -1906,12 +1909,13 @@ func (e *Engine) takeForRedispatch(
 		return false
 	}
 
+	// GORM's clock, as writeDeliveryStatus explains.
 	res := webhookDB.
 		Model(&database.Delivery{}).
 		Where(
 			"id = ? AND status = ?", deliveryID, eligible,
 		).
-		UpdateColumn("updated_at", time.Now())
+		UpdateColumn("updated_at", webhookDB.NowFunc())
 
 	if res.Error != nil {
 		e.log.Error(

internal/delivery/engine_lifecycle_test.go

@@ -2,16 +2,11 @@ package delivery_test
 
 import (
 	"context"
-	"io"
-	"net/http"
-	"net/http/httptest"
 	"path/filepath"
-	"sync"
 	"testing"
 	"time"
 
 	"github.com/google/uuid"
-	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 	"go.uber.org/fx"
 	"gorm.io/gorm/clause"
@@ -277,151 +272,6 @@ func TestEngine_StopHookHonoursStopTimeout(t *testing.T) {
 	requireStopHookExpires(t, lc.hooks[0], "delivery engine")
 }
 
-// seedHeldDelivery gives the setup's webhook an http target with
-// maxRetries, pointed at a receiver that keeps every request open until
-// the client gives up on it, and seeds one delivery to that target at
-// status. It returns the task that sends attempt attemptNum of the
-// delivery, and a channel that is closed when a request reaches the
-// receiver.
-func seedHeldDelivery(
-	t *testing.T,
-	s iSetup,
-	maxRetries int,
-	status database.DeliveryStatus,
-	attemptNum int,
-) (delivery.Task, <-chan struct{}) {
-	t.Helper()
-
-	arrived := make(chan struct{})
-
-	var once sync.Once
-
-	ts := httptest.NewServer(http.HandlerFunc(
-		func(_ http.ResponseWriter, r *http.Request) {
-			// The server notices the client hanging up only once the
-			// body has been read; until then r.Context() never ends.
-			_, _ = io.Copy(io.Discard, r.Body)
-
-			once.Do(func() { close(arrived) })
-
-			<-r.Context().Done()
-		},
-	))
-	t.Cleanup(ts.Close)
-
-	cfg := iHTTPConfig(ts.URL)
-	targetID := uuid.New().String()
-
-	iCreateWebhook(t, s.MainDB, s.WebhookID, "hook")
-	iCreateTarget(
-		t, s.MainDB, targetID, s.WebhookID, "held",
-		database.TargetTypeHTTP, cfg, maxRetries,
-	)
-
-	event := iSeedEvent(t, s.WebhookDB, s.WebhookID, `{"held":true}`)
-	d := iSeedDelivery(t, s.WebhookDB, event.ID, targetID, status)
-
-	bodyStr := event.Body
-
-	return iTask(
-		d, event, s.WebhookID, targetID, "held", cfg,
-		maxRetries, attemptNum, &bodyStr,
-	), arrived
-}
-
-// stopDuringAttempt waits until the receiver holds an attempt open, then
-// stops the engine through its real stop hook.
-func stopDuringAttempt(
-	t *testing.T, lc *recordingLifecycle, arrived <-chan struct{},
-) {
-	t.Helper()
-
-	select {
-	case <-arrived:
-	case <-time.After(5 * time.Second):
-		t.Fatal("the delivery attempt never reached the receiver")
-	}
-
-	require.NoError(t, lc.hooks[0].OnStop(context.Background()))
-}
-
-// requireRequeued runs restart recovery on the stopped engine and
-// requires it to queue task's attempt again on ch.
-func requireRequeued(
-	t *testing.T, s iSetup, ch <-chan delivery.Task, task delivery.Task,
-) {
-	t.Helper()
-
-	s.Engine.ExportRecoverWebhookDeliveries(
-		context.Background(), s.WebhookID,
-	)
-
-	select {
-	case got := <-ch:
-		assert.Equal(t, task.DeliveryID, got.DeliveryID)
-		assert.Equal(t, task.AttemptNum, got.AttemptNum)
-	case <-time.After(5 * time.Second):
-		t.Fatal("restart recovery did not queue the delivery again")
-	}
-}
-
-// TestEngine_StopLeavesFireAndForgetAttemptPending is the regression
-// test for a stop that turned an attempt in flight into a terminal
-// failure. Stopping the engine cancels the request; for a target with
-// no retries that was the delivery's only attempt, recorded as failed
-// with "context canceled", and nothing ever sent it again. The
-// delivery must instead stay pending, with no result, for restart
-// recovery to send.
-func TestEngine_StopLeavesFireAndForgetAttemptPending(t *testing.T) {
-	t.Parallel()
-
-	s := newISetup(t)
-	lc := startEngineViaHook(t, s.Engine)
-
-	task, arrived := seedHeldDelivery(
-		t, s, 0, database.DeliveryStatusPending, 1,
-	)
-
-	s.Engine.Notify([]delivery.Task{task})
-	stopDuringAttempt(t, lc, arrived)
-
-	iAssertStatus(
-		t, s.WebhookDB, task.DeliveryID, database.DeliveryStatusPending,
-	)
-	assert.Empty(t, iResults(t, s.WebhookDB, task.DeliveryID))
-
-	requireRequeued(t, s, s.Engine.ExportDeliveryCh(), task)
-}
-
-// TestEngine_StopLeavesLastRetryAttemptRetrying is the same regression
-// for a target with retries, on its last attempt: the cancelled attempt
-// used to exhaust the retries and end the delivery failed. It must stay
-// retrying with only its earlier attempt recorded, and restart recovery
-// must send that last attempt again.
-func TestEngine_StopLeavesLastRetryAttemptRetrying(t *testing.T) {
-	t.Parallel()
-
-	const maxRetries = 2
-
-	s := newISetup(t)
-	lc := startEngineViaHook(t, s.Engine)
-
-	task, arrived := seedHeldDelivery(
-		t, s, maxRetries, database.DeliveryStatusRetrying, maxRetries,
-	)
-	iSeedFailedResult(t, s.WebhookDB, task.DeliveryID)
-
-	s.Engine.ExportScheduleRetry(task, 0)
-	stopDuringAttempt(t, lc, arrived)
-
-	iAssertStatus(
-		t, s.WebhookDB, task.DeliveryID, database.DeliveryStatusRetrying,
-	)
-	assert.Len(t, iResults(t, s.WebhookDB, task.DeliveryID), 1)
-
-	requireRequeued(t, s, s.Engine.ExportRetryCh(), task)
-}
-
 // deliverToArchive gives the setup's webhook a database target,
 // runs one delivery to it through the running engine, and returns
 // the target's ID and archive file path. The archive writer holds

internal/delivery/engine_test.go

@@ -117,6 +117,18 @@ func seedDelivery(
 	return d
 }
 
+// assertStoredTime asserts that text, a timestamp as SQLite holds it,
+// is in the form GORM stores created_at in: the layout of
+// time.Time.String, with no " m=+…" monotonic clock reading after it.
+func assertStoredTime(t *testing.T, text string) {
+	t.Helper()
+
+	_, err := time.Parse(
+		"2006-01-02 15:04:05.999999999 -0700 MST", text,
+	)
+	assert.NoError(t, err, "stored as %q", text)
+}
+
 // httpDeliveryFixture holds the task and delivery needed
 // for HTTP delivery tests.
 type httpDeliveryFixture struct {

internal/delivery/inflight_test.go

@@ -462,7 +462,8 @@ func TestScheduledRetryIsNotSweptDuringBackoff(t *testing.T) {
 
 // TestRedispatchStampsTheRow pins the cadence control: a stranded
 // delivery that has just been handed out is not selected again by the
-// next tick a minute later.
+// next tick a minute later. The stamp is stored in the same form as
+// created_at.
 func TestRedispatchStampsTheRow(t *testing.T) {
 	t.Parallel()
 
@@ -493,4 +494,13 @@ func TestRedispatchStampsTheRow(t *testing.T) {
 		"a re-dispatched delivery must be stamped so the "+
 			"next tick does not select it again",
 	)
+
+	var createdAt, updatedAt string
+
+	require.NoError(t, s.WebhookDB.Raw(
+		`SELECT CAST(created_at AS TEXT), CAST(updated_at AS TEXT)
+		FROM deliveries WHERE id = ?`, d.ID,
+	).Row().Scan(&createdAt, &updatedAt))
+	assertStoredTime(t, createdAt)
+	assertStoredTime(t, updatedAt)
 }

internal/delivery/target_database_archive.go

@@ -277,7 +277,11 @@ func (w *archiveWriter) write(
 		}
 	}
 
-	row.ArchivedAt = time.Now()
+	// GORM's clock, the one that stamps created_at in the other
+	// databases, so this is stored in the same form. A bare time.Now()
+	// carries a monotonic clock reading, which the driver would store
+	// as an " m=+…" suffix.
+	row.ArchivedAt = w.db.NowFunc()
 
 	err := w.db.Create(&row).Error
 	if err != nil {

internal/delivery/target_database_test.go

@@ -150,6 +150,13 @@ func TestArchiveWriter_WritesRow(t *testing.T) {
 	assert.Equal(t, row.ContentType, got[0].ContentType)
 	assert.JSONEq(t, `{"hello":"world"}`, got[0].Body)
 	assert.False(t, got[0].ArchivedAt.IsZero())
+
+	var archivedAt string
+
+	require.NoError(t, w.DB().Raw(
+		"SELECT CAST(archived_at AS TEXT) FROM archived_events",
+	).Row().Scan(&archivedAt))
+	assertStoredTime(t, archivedAt)
 }
 
 func TestArchiveWriter_RecreatesAfterRemoval(

internal/delivery/target_http.go

@@ -57,11 +57,7 @@ type httpCore struct {
 // recorded and no circuit breaker is consulted. A positive
 // maxRetries gates the attempt on the circuit breaker and
 // schedules a backed-off retry on failure.
-//
-// ctx is the context attempt sends its request with. Stopping the
-// engine cancels it; see interruptedByStop.
 func (c *httpCore) deliver(
-	ctx context.Context,
 	webhookDB *gorm.DB,
 	d *database.Delivery,
 	task *Task,
@@ -70,57 +66,23 @@ func (c *httpCore) deliver(
 	attempt func() attemptResult,
 ) {
 	if maxRetries == 0 {
-		c.fireAndForget(ctx, webhookDB, d, attempt())
+		c.fireAndForget(webhookDB, d, attempt())
 
 		return
 	}
 
 	c.withRetry(
-		ctx, webhookDB, d, task, sched, maxRetries, attempt,
+		webhookDB, d, task, sched, maxRetries, attempt,
 	)
 }
 
-// interruptedByStop reports whether an attempt failed because the
-// engine is stopping, which cancels the context its request was sent
-// with. Such an attempt is not recorded: no DeliveryResult, no circuit
-// breaker outcome, no status change. The delivery stays pending or
-// retrying, and startup recovery sends it again on the next start.
-// The request did go out, so the attempt metrics still count it.
-//
-// A target's own timeout leaves that context alone, so its attempt is
-// still recorded as the failure it is.
-func (c *httpCore) interruptedByStop(
-	ctx context.Context,
-	d *database.Delivery,
-	res attemptResult,
-) bool {
-	if res.success || ctx.Err() == nil {
-		return false
-	}
-
-	c.eng.log.Warn(
-		"delivery attempt interrupted by shutdown; not recorded, "+
-			"it is sent again on the next start",
-		"delivery_id", d.ID,
-		"event_id", d.EventID,
-		"target_id", d.TargetID,
-	)
-
-	return true
-}
-
 func (c *httpCore) fireAndForget(
-	ctx context.Context,
 	webhookDB *gorm.DB,
 	d *database.Delivery,
 	res attemptResult,
 ) {
 	c.eng.observeAttempt(d.Target.Type, res.elapsed())
 
-	if c.interruptedByStop(ctx, d, res) {
-		return
-	}
-
 	err := c.eng.recordResult(
 		webhookDB, d, 1, res.success,
 		res.statusCode, res.respBody, res.errMsg,
@@ -148,7 +110,6 @@ func (c *httpCore) fireAndForget(
 }
 
 func (c *httpCore) withRetry(
-	ctx context.Context,
 	webhookDB *gorm.DB,
 	d *database.Delivery,
 	task *Task,
@@ -172,10 +133,6 @@ func (c *httpCore) withRetry(
 
 	c.eng.observeAttempt(d.Target.Type, res.elapsed())
 
-	if c.interruptedByStop(ctx, d, res) {
-		return
-	}
-
 	err := c.eng.recordResult(
 		webhookDB, d, attemptNum, res.success,
 		res.statusCode, res.respBody, res.errMsg,
@@ -438,7 +395,7 @@ func (t *httpTarget) Deliver(
 	}
 
 	t.deliver(
-		ctx, webhookDB, d, task, sched,
+		webhookDB, d, task, sched,
 		d.Target.MaxRetries, attempt,
 	)
 }

internal/delivery/target_slack.go

@@ -82,7 +82,7 @@ func (t *slackTarget) Deliver(
 	}
 
 	t.deliver(
-		ctx, webhookDB, d, task, sched,
+		webhookDB, d, task, sched,
 		d.Target.MaxRetries, attempt,
 	)
 }