webhooker/internal/server/recoverer_test.go

package server_test

import (
	"bytes"
	"context"
	"encoding/json"
	"fmt"
	"net/http"
	"net/http/httptest"
	"os"
	"os/exec"
	"strings"
	"testing"

	"github.com/getsentry/sentry-go"
	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
	"sneak.berlin/go/webhooker/internal/middleware"
	"sneak.berlin/go/webhooker/internal/server"
)

// panicProbeMarker is the value the probe handler panics with. The
// defect this pins lost it entirely: what reached the operator was the
// recoverer's own secondary panic, naming chi's decorateFuncCallLine
// and nothing about the fault that caused it.
const panicProbeMarker = "QQPRODUCTIONPANICVALUEQQ"

// panicChildEnv, when set, tells the re-executed test binary to run
// the child half of the fd-level probe below.
const panicChildEnv = "WEBHOOKER_PANIC_PROBE_CHILD"

// panicChildResultPrefix labels the child's own one-line report of
// what the HTTP client saw, so the parent can find it among whatever
// else lands on the child's standard output.
const panicChildResultPrefix = "PANIC-PROBE-RESULT "

// stackTruncationMarker mirrors what internal/middleware appends to a
// field it cut. It is duplicated rather than exported, as the access
// log's budgets are, so that changing it has to be restated here
// deliberately.
const stackTruncationMarker = "[truncated]"

// TestPanicThroughProductionRouter drives a handler panic through the
// shipped router, over a real server, in a subprocess whose actual
// file descriptors are captured.
//
// Every part of that is load-bearing.
//
// A subprocess, because the question is what reaches fd 1 and fd 2 of
// the process an operator runs. The defect's signature was 0 bytes on
// standard error and a 2,772-byte record on standard output describing
// chi's own crash, and neither is visible to a test that swaps the
// logger for a buffer.
//
// A real server, because a panicking handler under chi's Recoverer
// dropped the connection: the client got EOF, not a status. An
// httptest.ResponseRecorder has no connection to drop and would have
// recorded the same unwritten response either way, which is why this
// defect survived the existing suite.
//
// The production router, because the placement of the recoverer among
// the other global middleware is part of the fix.
func TestPanicThroughProductionRouter(t *testing.T) {
	t.Parallel()

	if os.Getenv(panicChildEnv) != "" {
		t.Skip("child half; run by the parent below")
	}

	//nolint:gosec // Re-executing this test binary, with a fixed arg.
	cmd := exec.CommandContext(
		t.Context(), os.Args[0],
		"-test.run", "^TestPanicProbeChild$",
	)

	cmd.Env = append(os.Environ(), panicChildEnv+"=1")

	var stdout, stderr bytes.Buffer

	cmd.Stdout = &stdout
	cmd.Stderr = &stderr

	require.NoError(
		t, cmd.Run(),
		"child failed\nstdout:\n%s\nstderr:\n%s",
		stdout.String(), stderr.String(),
	)

	assertPanicProbeOutput(t, stdout.String(), stderr.String())
}

// assertPanicProbeOutput holds the child's descriptors to what a
// working recoverer produces.
func assertPanicProbeOutput(t *testing.T, stdout, stderr string) {
	t.Helper()

	result := ""

	var record map[string]any

	for line := range strings.SplitSeq(stdout, "\n") {
		if after, found := strings.CutPrefix(
			line, panicChildResultPrefix,
		); found {
			result = after

			continue
		}

		if !strings.HasPrefix(line, `{"time"`) {
			continue
		}

		decoded := map[string]any{}
		if json.Unmarshal([]byte(line), &decoded) != nil {
			continue
		}

		if decoded["msg"] == "handler panic" {
			require.Nil(
				t, record, "one panic record expected, got two",
			)

			record = decoded

			assert.LessOrEqual(
				t, len(line), middleware.MaxPanicLogLineBytes,
				"the panic record must hold its stated ceiling",
			)

			t.Logf(
				"panic record through the shipped chain: %d bytes "+
					"(ceiling %d)",
				len(line), middleware.MaxPanicLogLineBytes,
			)
		}
	}

	// What the client got. Under the defect this read
	// `status=0 err=... EOF`.
	require.Equal(
		t, "status=500 err=<nil>", result,
		"the client must receive a 500, not a dropped connection",
	)

	// What the operator got. Under the defect there was no such
	// record: standard output carried net/http reporting chi's own
	// crash, at INFO, with the original panic value nowhere in it.
	require.NotNil(
		t, record,
		"no structured panic record reached standard output",
	)
	assert.Equal(t, "ERROR", record["level"])
	assert.Equal(t, panicProbeMarker, record["panic"])
	assert.Equal(t, false, record["response_committed"])

	stack, ok := record["stack"].(string)
	require.True(t, ok)
	assert.Contains(t, stack, "panicProbeHandler")
	assert.NotContains(
		t, stack, stackTruncationMarker,
		"the shipped middleware chain's own stack must fit the "+
			"stack budget without being cut",
	)
	t.Logf("stack through the shipped chain: %d bytes", len(stack))

	// The secondary panic, in every form it took. net/http's report
	// is the tell: it only logs a request when something escaped the
	// handler chain.
	assert.NotContains(t, stdout, "http: panic serving")
	assert.NotContains(t, stdout, "slice bounds out of range")
	assert.NotContains(t, stdout, "decorateFuncCallLine")
	assert.Empty(
		t, strings.TrimSpace(stderr),
		"nothing may reach standard error",
	)
}

// panicProbeHandler is the panicking route the child installs. It is a
// named function so the stack assertion has something to look for.
func panicProbeHandler(http.ResponseWriter, *http.Request) {
	panic(panicProbeMarker)
}

// TestPanicProbeChild is the child half of the probe above. It runs
// only when re-executed with panicChildEnv set; in an ordinary run it
// returns immediately.
//
// It writes its result to standard output with a prefix rather than
// asserting, because the assertions belong to the parent, which is the
// only side that can see both descriptors.
func TestPanicProbeChild(t *testing.T) {
	t.Parallel()

	if os.Getenv(panicChildEnv) == "" {
		return
	}

	env := newTestEnv(t)

	router := server.NewRouterWithProbeForTest(
		t, env.log, env.cfg, env.mw, env.hnd,
		false, panicProbeHandler,
	)

	srv := httptest.NewServer(router)
	defer srv.Close()

	req, err := http.NewRequestWithContext(
		context.Background(), http.MethodGet,
		srv.URL+server.ProbePattern, nil,
	)
	require.NoError(t, err)

	status := 0

	resp, err := srv.Client().Do(req)
	if err == nil {
		status = resp.StatusCode

		_ = resp.Body.Close()
	}

	// Written to the descriptor rather than through the testing
	// package's own output, because fd 1 is exactly what the parent
	// is measuring.
	_, writeErr := fmt.Fprintf(
		os.Stdout, "%sstatus=%d err=%v\n",
		panicChildResultPrefix, status, err,
	)
	require.NoError(t, writeErr)
}

// TestSentryStillSeesAPanic pins the relationship the recoverer's
// placement has to preserve. sentryhttp is registered with
// Repanic: true, inside the recoverer, so an operator with SENTRY_DSN
// set keeps the report and the client still gets a 500. Registered the
// other way round, the SDK would swallow the panic and the recoverer
// would never see it.
func TestSentryStillSeesAPanic(t *testing.T) {
	t.Parallel()

	env := newTestEnv(t)

	transport := &captureTransport{}

	opts := server.SentryClientOptionsForTest(
		"https://public@sentry.invalid/1", "webhooker-test",
	)
	opts.Transport = transport

	client, err := sentry.NewClient(opts)
	require.NoError(t, err)

	router := server.NewRouterWithProbeForTest(
		t, env.log, env.cfg, env.mw, env.hnd,
		true, panicProbeHandler,
	)

	req := httptest.NewRequestWithContext(
		sentry.SetHubOnContext(
			context.Background(),
			sentry.NewHub(client, sentry.NewScope()),
		),
		http.MethodGet, server.ProbePattern, nil,
	)

	w := httptest.NewRecorder()
	router.ServeHTTP(w, req)

	assert.Equal(
		t, http.StatusInternalServerError, w.Code,
		"the recoverer must still answer what sentryhttp re-raised",
	)

	events := transport.events
	require.Len(t, events, 1, "Sentry must still see the panic")
	assert.Equal(t, sentry.LevelFatal, events[0].Level)
	// The SDK renders a string panic value as the event message
	// rather than an exception, so the whole payload is checked for
	// the value rather than one field of it.
	assert.Contains(
		t, marshalEvent(t, events[0]), panicProbeMarker,
	)
}