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

internal/handlers/logbound_test.go

@@ -1,19 +1,15 @@
 package handlers_test
 
-// The handler-side half of the log-field audit. Two slog calls in
-// this package reach a value an UNAUTHENTICATED client picks outright
-// and of a length it picks outright:
+// The handler-side half of the log-field audit. The slog calls in
+// this package that reach a value an UNAUTHENTICATED client picks
+// outright, and of a length it picks outright, are the failed-login
+// DEBUG lines, whose username is a form field.
 //
-//   - the unknown-entrypoint DEBUG line on /h/{uuid}, whose
-//     path segment matched no stored entrypoint and so is bounded by
-//     nothing;
-//   - the failed-login DEBUG lines, whose username is a form field.
-//
-// Both are at DEBUG, which is off in production by default. That is
+// They are at DEBUG, which is off in production by default. That is
 // not a bound: an operator turning DEBUG on to diagnose a flood must
-// not thereby hand the flood an unbounded write. Both spend the same
-// internal/logfield budget as the access log, and both are held here
-// to middleware.MaxAccessLogLineBytes.
+// not thereby hand the flood an unbounded write. They spend the same
+// internal/logfield budget as the access log, and are held here to
+// middleware.MaxAccessLogLineBytes.
 //
 // The two login lines past the username lookup — "invalid password"
 // and "user logged in" — carry the same cap without needing it, since
@@ -260,43 +256,6 @@ func postLoginWithPassword(
 	return w.Code
 }
 
-// TestUnknownEntrypoint_LogLineDoesNotTrackPathSize drives 8 KB of
-// client-chosen path at the unauthenticated receiver's
-// unknown-entrypoint DEBUG line and holds it to the same ceiling the
-// access log states.
-func TestUnknownEntrypoint_LogLineDoesNotTrackPathSize(t *testing.T) {
-	t.Parallel()
-
-	for handlerName, newHandler := range logHandlers() {
-		for fillName, fill := range escapeFills() {
-			t.Run(handlerName+"/"+fillName, func(t *testing.T) {
-				t.Parallel()
-
-				h, buf := capturingHandlers(t, newHandler)
-				router := receiverRouter(h)
-
-				for i := range floodRequests {
-					assert.Equal(
-						t,
-						http.StatusNotFound,
-						postReceiver(
-							t, router,
-							oversizedFill(fill)+
-								strings.Repeat("y", i),
-						),
-					)
-				}
-
-				lines := logLines(t, buf)
-				require.Len(t, lines, floodRequests)
-				assertNoClientText(t, buf)
-
-				assertBoundedFlood(t, buf.Len())
-			})
-		}
-	}
-}
-
 // TestFailedLogin_LogLineDoesNotTrackUsernameSize drives 8 KB of
 // client-chosen username at the unauthenticated login endpoint's
 // DEBUG line and holds it to the same ceiling.

internal/handlers/webhook.go

@@ -10,7 +10,6 @@ import (
 	"gorm.io/gorm"
 	"sneak.berlin/go/webhooker/internal/database"
 	"sneak.berlin/go/webhooker/internal/delivery"
-	"sneak.berlin/go/webhooker/internal/logfield"
 	"sneak.berlin/go/webhooker/internal/middleware"
 )
 
@@ -49,14 +48,13 @@ func (h *Handlers) HandleWebhook() http.HandlerFunc {
 			return
 		}
 
-		// Logged only once the UUID is known to name a real
-		// entrypoint. The UUID comes straight out of the path on
-		// the one unauthenticated endpoint, so logging it before
-		// the lookup let a client write an INFO line per invented
-		// path; the request itself is already in the access log
-		// and a miss is already logged at DEBUG.
+		// Logged only once the lookup has found the entrypoint, so
+		// an invented path writes no INFO line; a miss is logged at
+		// DEBUG. The entrypoint is named by its ID: the UUID is its
+		// credential and is never logged.
 		h.log.Info("webhook request received",
-			"entrypoint_uuid", entrypointUUID,
+			"entrypoint_id", entrypoint.ID,
+			"webhook_id", entrypoint.WebhookID,
 			"method", r.Method,
 			"remoteIP", middleware.RemoteIP(r),
 			"clientIP", middleware.ClientIP(r),
@@ -133,17 +131,10 @@ func (h *Handlers) lookupEntrypoint(
 		"path = ?", entrypointUUID,
 	).First(&entrypoint)
 	if result.Error != nil {
-		// The receiver is unauthenticated and /h/{uuid}
-		// matches any single segment, so this value is entirely
-		// client-chosen on exactly the branch where the lookup
-		// failed. DEBUG is off by default; the cap is what keeps
-		// turning it on from restoring an unbounded write.
-		h.log.Debug(
-			"entrypoint not found",
-			"path", logfield.Truncate(
-				entrypointUUID, logfield.MaxBytes,
-			),
-		)
+		// Not even an unknown UUID is logged. The receiver's log
+		// lines never carry the path segment, which is a credential
+		// whenever it names an entrypoint.
+		h.log.Debug("entrypoint not found")
 		http.NotFound(w, r)
 
 		return entrypoint, false

internal/handlers/webhook_test.go

@@ -12,12 +12,15 @@ import (
 	"testing"
 
 	"github.com/go-chi/chi"
+	"github.com/google/uuid"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
+	"gorm.io/gorm/clause"
 	"sneak.berlin/go/webhooker/internal/config"
 	"sneak.berlin/go/webhooker/internal/database"
 	"sneak.berlin/go/webhooker/internal/handlers"
 	"sneak.berlin/go/webhooker/internal/middleware"
+	"sneak.berlin/go/webhooker/internal/middleware/middlewaretest"
 )
 
 // TestHandleWebhook_LogsClientNextToThePeer checks that the
@@ -99,6 +102,87 @@ func TestHandleWebhook_LogsClientNextToThePeer(t *testing.T) {
 	}
 }
 
+// TestHandleWebhook_LogsNoEntrypointUUID sends an accepted event, a
+// request over the receiver rate limit and a request for an unknown
+// UUID through the receiver as routes.go mounts it, and checks that
+// nothing logged, at any level, carries either UUID.
+func TestHandleWebhook_LogsNoEntrypointUUID(t *testing.T) {
+	t.Parallel()
+
+	var (
+		h  *handlers.Handlers
+		db *database.Database
+	)
+
+	cfg := &config.Config{DataDir: t.TempDir(), ReceiverRateLimit: 1}
+
+	app := newTestAppWithConfig(t, cfg, &h, &db)
+	app.RequireStart()
+
+	t.Cleanup(app.RequireStop)
+
+	buf := new(bytes.Buffer)
+	log := slog.New(slog.NewJSONHandler(
+		buf, &slog.HandlerOptions{Level: slog.LevelDebug},
+	))
+	h.SetLogForTest(log)
+	mw := middlewaretest.New(t, log, cfg, nil)
+
+	webhook := seedWebhook(t, db)
+	entrypoint := &database.Entrypoint{
+		WebhookID: webhook.ID,
+		Path:      uuid.New().String(),
+		Active:    true,
+	}
+	require.NoError(t, db.DB().Omit(clause.Associations).
+		Create(entrypoint).Error)
+
+	unknownUUID := uuid.New().String()
+
+	router := chi.NewRouter()
+	router.Use(mw.Logging())
+	router.With(mw.ReceiverRateLimit()).HandleFunc(
+		middleware.ReceiverRoute, h.HandleWebhook(),
+	)
+
+	// In order: the limit is one request per minute per path, so the
+	// second request for the known UUID is the rejected one.
+	for _, step := range []struct {
+		entrypointUUID string
+		wantStatus     int
+	}{
+		{entrypoint.Path, http.StatusOK},
+		{entrypoint.Path, http.StatusTooManyRequests},
+		{unknownUUID, http.StatusNotFound},
+	} {
+		req := httptest.NewRequestWithContext(
+			context.Background(), http.MethodPost,
+			"/h/"+step.entrypointUUID, strings.NewReader("{}"),
+		)
+		w := httptest.NewRecorder()
+		router.ServeHTTP(w, req)
+
+		require.Equal(t, step.wantStatus, w.Code)
+	}
+
+	// The lines this test is about were all written, so the checks
+	// below are not passing on an empty log.
+	for _, msg := range []string{
+		"webhook request received",
+		"webhook receiver rate limit exceeded",
+		"entrypoint not found",
+	} {
+		assert.Contains(t, buf.String(), `"msg":"`+msg+`"`)
+	}
+
+	assert.NotContains(t, buf.String(), entrypoint.Path)
+	assert.NotContains(t, buf.String(), unknownUUID)
+
+	line := receivedLine(t, buf)
+	assert.Equal(t, entrypoint.ID, line["entrypoint_id"])
+	assert.Equal(t, webhook.ID, line["webhook_id"])
+}
+
 // receivedLine returns the one "webhook request received" line in the
 // captured JSON log.
 func receivedLine(t *testing.T, buf *bytes.Buffer) map[string]any {