webhooker/internal/handlers/webhook_test.go

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/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
// 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"])
		})
	}
}

// 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 {
	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]
}