Log the client address next to the peer address (closes #270)

Behind a trusted proxy every log line named only the proxy, so abuse could not be traced from webhooker's own logs although the rate limiters already knew the client. The access log, the rate-limit rejection lines, the CSRF warning and the receiver's request line now carry clientIP next to remoteIP. remoteIP still means the connecting peer; clientIP is the address the rate limiters key on, the forwarded client when the peer is inside TRUSTED_PROXIES, worked out once per request by the same code. The README says the field is only as trustworthy as TRUSTED_PROXIES. The access log's 2,560-byte line ceiling holds with the field charged, and a size case with an oversized X-Forwarded-For pins it.

Model: opus-5-5

internal/handlers/webhook_test.go

@@ -0,0 +1,124 @@
+package handlers_test
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"net/netip"
+	"strings"
+	"testing"
+
+	"github.com/go-chi/chi"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"sneak.berlin/go/webhooker/internal/config"
+	"sneak.berlin/go/webhooker/internal/database"
+	"sneak.berlin/go/webhooker/internal/handlers"
+	"sneak.berlin/go/webhooker/internal/middleware"
+)
+
+// TestHandleWebhook_LogsClientNextToThePeer checks that the
+// receiver's "webhook request received" line carries both addresses:
+// remoteIP, the connecting peer, and clientIP, the client the access
+// log attributes the request to.
+func TestHandleWebhook_LogsClientNextToThePeer(t *testing.T) {
+	t.Parallel()
+
+	// untrustedPeer is outside the trusted 10.0.0.0/8, so its
+	// X-Forwarded-For is ignored and it is the client.
+	const untrustedPeer = "192.0.2.10"
+
+	cases := map[string]struct {
+		peer       string
+		wantRemote string
+		wantClient string
+	}{
+		"trusted proxy with a forwarded chain": {
+			peer:       "10.0.0.1:44444",
+			wantRemote: "10.0.0.1",
+			wantClient: "198.51.100.7",
+		},
+		"untrusted peer": {
+			peer:       untrustedPeer + ":5555",
+			wantRemote: untrustedPeer,
+			wantClient: untrustedPeer,
+		},
+	}
+
+	for name, tc := range cases {
+		t.Run(name, func(t *testing.T) {
+			t.Parallel()
+
+			var (
+				h  *handlers.Handlers
+				mw *middleware.Middleware
+				db *database.Database
+			)
+
+			app := newTestAppWithConfig(t, &config.Config{
+				DataDir: t.TempDir(),
+				TrustedProxies: []netip.Prefix{
+					netip.MustParsePrefix("10.0.0.0/8"),
+				},
+			}, &h, &mw, &db)
+			app.RequireStart()
+
+			t.Cleanup(app.RequireStop)
+
+			buf := new(bytes.Buffer)
+			h.SetLogForTest(slog.New(slog.NewJSONHandler(buf, nil)))
+
+			webhook := seedWebhook(t, db)
+			seedEntrypoint(t, db, webhook.ID)
+
+			// Logging is what works the client address out, so the
+			// request goes through it as it does in production.
+			router := chi.NewRouter()
+			router.Use(mw.Logging())
+			router.Post("/h/{uuid}", h.HandleWebhook())
+
+			req := httptest.NewRequestWithContext(
+				context.Background(), http.MethodPost,
+				"/h/ep-"+webhook.ID, strings.NewReader("{}"),
+			)
+			req.RemoteAddr = tc.peer
+			req.Header.Set("X-Forwarded-For", "198.51.100.7, 10.0.0.2")
+
+			w := httptest.NewRecorder()
+			router.ServeHTTP(w, req)
+
+			require.Equal(t, http.StatusOK, w.Code)
+
+			line := receivedLine(t, buf)
+			assert.Equal(t, tc.wantRemote, line["remoteIP"])
+			assert.Equal(t, tc.wantClient, line["clientIP"])
+		})
+	}
+}
+
+// receivedLine returns the one "webhook request received" line in the
+// captured JSON log.
+func receivedLine(t *testing.T, buf *bytes.Buffer) map[string]any {
+	t.Helper()
+
+	var found []map[string]any
+
+	for line := range strings.SplitSeq(
+		strings.TrimSpace(buf.String()), "\n",
+	) {
+		var entry map[string]any
+
+		require.NoError(t, json.Unmarshal([]byte(line), &entry))
+
+		if entry["msg"] == "webhook request received" {
+			found = append(found, entry)
+		}
+	}
+
+	require.Len(t, found, 1)
+
+	return found[0]
+}