Keep the entrypoint UUID out of webhooker's own logs (closes #531)

On the receiver route the access log and the per-entrypoint 429 line
name the route pattern whatever the status. A request chi never routed,
such as a dev-mode CORS preflight to the receiver, logs (unmatched)
whatever the status. The received line names the entrypoint and webhook
IDs, and the unknown-entrypoint line logs no path. The pattern is
middleware.ReceiverRoute, which routes.go registers the receiver with.

The README says the proxy's access log holds the UUID and must be
protected like the URL, and its access-log, rate-limit, Sentry and
log-size passages now match the code.

Model: opus-5-5

README.md

@@ -2441,15 +2441,18 @@ route it logs the route pattern `/h/{uuid}` whatever the status, because the
 concrete path carries the entrypoint UUID, which is the entrypoint's credential
 (see
 [The entrypoint URL is the authentication secret](#the-entrypoint-url-is-the-authentication-secret)).
-On every other route, a 3xx or 4xx response logs the chi route pattern — such as
-`/user/{username}//`, or the literal `(unmatched)` when the request hit no route
-at all — in place of the concrete URL. Those are the outcomes an unauthenticated
-client can drive for free: a 404 on any invented path, a login redirect on any
-invented profile path. Logging the URL there would let a flood write text of its
-own choosing, at a length of its own choosing, into the log. 2xx and 5xx
-responses keep the concrete path — a success resolved against a static route or
-against the operator's own data, and a 5xx is a bug in this service, where the
-exact path is the evidence and no client can provoke one at will.
+A request chi never routed, because it matched no route or because a middleware
+answered it first, logs the literal `(unmatched)` whatever the status. In the
+`dev` environment the CORS middleware answers a preflight that way, so a
+preflight to the receiver does not log its UUID either. On every other route, a
+3xx or 4xx response logs the chi route pattern, such as `/user/{username}//`, in
+place of the concrete URL. Those are the outcomes an unauthenticated client can
+drive for free: a 404 on any invented path, a login redirect on any invented
+profile path. Logging the URL there would let a flood write text of its own
+choosing, at a length of its own choosing, into the log. 2xx and 5xx responses
+keep the concrete path — a success resolved against a static route or against
+the operator's own data, and a 5xx is a bug in this service, where the exact
+path is the evidence and no client can provoke one at will.
 
 The query string is never logged; it is replaced by the fixed marker
 `?(redacted)`. It is client-chosen on every route, and

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
-// on its target's delivered or failed total.
+// finished, set only when it becomes delivered or failed and stored in
+// 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

@@ -1701,8 +1701,11 @@ func writeDeliveryStatus(
 			database.DeliveryStatusFailed,
 		}).
 		Updates(map[string]any{
-			"status":      status,
-			"finished_at": time.Now(),
+			"status": status,
+			// 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_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/middleware/accesslog_test.go

@@ -703,6 +703,42 @@ func TestAccessLog_ReceiverNeverLogsTheUUID(t *testing.T) {
 	}
 }
 
+// TestAccessLog_ReceiverPreflightNeverLogsTheUUID sends a CORS
+// preflight to the receiver in dev, in the production middleware
+// order. CORS answers it with 200 before chi routes it, so the line
+// names no route and carries no UUID.
+func TestAccessLog_ReceiverPreflightNeverLogsTheUUID(t *testing.T) {
+	t.Parallel()
+
+	m, buf := capturingMiddleware(t)
+
+	router := chi.NewRouter()
+	router.Use(m.Logging())
+	router.Use(m.CORS())
+	router.HandleFunc(
+		middleware.ReceiverRoute,
+		func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(http.StatusOK)
+		},
+	)
+
+	req := httptest.NewRequestWithContext(
+		context.Background(), http.MethodOptions,
+		"/h/"+knownEntrypointUUID, nil,
+	)
+	req.Header.Set("Origin", "https://sender.example")
+	req.Header.Set("Access-Control-Request-Method", http.MethodPost)
+
+	w := httptest.NewRecorder()
+	router.ServeHTTP(w, req)
+	assert.Equal(t, http.StatusOK, w.Code)
+
+	entries := accessLogEntries(t, buf)
+	require.Len(t, entries, 1)
+	assert.Equal(t, unmatchedRouteLiteral, entries[0]["url"])
+	assert.NotContains(t, buf.String(), knownEntrypointUUID)
+}
+
 func TestAccessLog_ServerErrorKeepsConcreteURL(t *testing.T) {
 	t.Parallel()
 

internal/middleware/middleware.go

@@ -303,7 +303,9 @@ func concreteLogURL(r *http.Request) string {
 // accessLogURL returns the value for the access log's url field.
 //
 // On ReceiverRoute it is the route pattern whatever the status, so
-// the entrypoint UUID in the path is never logged.
+// the entrypoint UUID in the path is never logged. A request chi never
+// routed gets unmatchedRoute whatever the status, for the same reason:
+// in dev, CORS answers a preflight to the receiver before routing.
 //
 // On every other route, 2xx and 5xx responses get the concrete path
 // (see concreteLogURL). A success resolved against a static route or
@@ -312,19 +314,19 @@ func concreteLogURL(r *http.Request) string {
 // provoke at will.
 //
 // 3xx and 4xx responses get the chi route pattern instead. Those are
-// the outcomes an unauthenticated client drives for free: 303 to the
-// login page on any invented /user/ path, 404 on any path that
-// matches no route. Logging the concrete URL there lets a flood
-// write attacker-chosen text, of attacker-chosen length, into the
-// operator's log at one line per request. The pattern comes from the
-// router's own table, so it is bounded by the service's routes while
-// still naming which class of request was rejected.
+// the outcomes an unauthenticated client drives for free, such as a
+// 303 to the login page on any invented /user/ path. Logging the
+// concrete URL there lets a flood write attacker-chosen text, of
+// attacker-chosen length, into the operator's log at one line per
+// request. The pattern comes from the router's own table, so it is
+// bounded by the service's routes while still naming which class of
+// request was rejected.
 //
 // The pattern is only populated once routing has run, so this must be
 // called after the handler returns, not before.
 func accessLogURL(r *http.Request, status int) string {
 	pattern := routePatternID(r.Context())
-	if pattern == ReceiverRoute {
+	if pattern == ReceiverRoute || pattern == unmatchedRoute {
 		return pattern
 	}