smallwebwaf/internal/rproxy/rproxy_test.go

package rproxy_test

import (
	"bufio"
	"bytes"
	"encoding/json"
	"io"
	"log/slog"
	"maps"
	"net"
	"net/http"
	"net/http/httptest"
	"slices"
	"strings"
	"sync"
	"testing"
	"time"

	"sneak.berlin/go/smallwebwaf/internal/config"
	"sneak.berlin/go/smallwebwaf/internal/proxy"
	"sneak.berlin/go/smallwebwaf/internal/requestlog"
	"sneak.berlin/go/smallwebwaf/internal/rproxy"
)

const (
	// waitLimit bounds how long a test waits for what should happen.
	waitLimit = 10 * time.Second
	// pollInterval is how often a test looks for a log line.
	pollInterval = 10 * time.Millisecond
	// localhost is where every test server listens, and so the address rproxy
	// sees each test's requests come from.
	localhost = "127.0.0.1"
	// site is the host the tests' requests ask for.
	site = "site.example"
	// greeting is what the tests' app answers by default.
	greeting = "hello from the app"
	// nowhere is a URL nothing listens at: port 9 is the discard service, which
	// nothing on a test host runs.
	nowhere = "http://127.0.0.1:9"
)

// The settings the tests set.
const (
	timeoutSetting     = "SWRP_TIMEOUT_MS"
	defaultDisposition = "SWRP_DEFAULT_DISPOSITION"
	trustedProxies     = "SWRP_TRUSTED_PROXIES"
	maxRequestSize     = "SWRP_MAX_REQUEST_SIZE"
	maxResponseSize    = "SWRP_MAX_RESPONSE_SIZE"
	maxRequestTime     = "SWRP_MAX_REQUEST_TIME_MS"
	maxResponseTime    = "SWRP_MAX_RESPONSE_TIME_MS"
)

// The headers the tests set and look at.
const (
	dispositionHeader    = proxy.DispositionHeader
	forwardedForHeader   = "X-Forwarded-For"
	forwardedProtoHeader = "X-Forwarded-Proto"
	requestIDHeader      = "X-Request-ID"
	asnHeader            = "X-Client-Asn"
	countryHeader        = "X-Client-Country"
	contentLengthHeader  = "Content-Length"
	// fromServeWAFHeader is a header the stand-in for servewaf adds to a deny.
	fromServeWAFHeader = "X-From-Servewaf"
)

// What the stand-in for servewaf answers.
const (
	dispositionAllow = proxy.DispositionAllow
	dispositionDeny  = proxy.DispositionDeny
	dispositionClose = proxy.DispositionClose
	// deniedBody is the body of a deny.
	deniedBody = "refused by servewaf"
)

// output collects what rproxy writes on stdout.
type output struct {
	mu  sync.Mutex
	buf bytes.Buffer
}

// Write adds lines rproxy writes.
func (o *output) Write(p []byte) (int, error) {
	o.mu.Lock()
	defer o.mu.Unlock()

	return o.buf.Write(p)
}

// requestLine waits for the request log line of a test's one request.
func (o *output) requestLine(t *testing.T) map[string]any {
	t.Helper()

	deadline := time.Now().Add(waitLimit)
	for time.Now().Before(deadline) {
		o.mu.Lock()
		text := o.buf.String()
		o.mu.Unlock()

		for line := range strings.Lines(text) {
			var fields map[string]any

			err := json.Unmarshal([]byte(line), &fields)
			if err != nil {
				t.Fatalf("output line %q is not JSON: %v", line, err)
			}

			if fields["type"] == "request" {
				return fields
			}
		}

		time.Sleep(pollInterval)
	}

	t.Fatal("no request log line")

	return nil
}

// question is what the stand-in for servewaf received as a question.
type question struct {
	method, target, host string
	header               http.Header
	body                 []byte
	contentLength        int64
	transferEncoding     []string
}

// serveWAF is a stand-in for servewaf that answers each question as answer
// does, and keeps the questions and the reports it gets.
type serveWAF struct {
	*httptest.Server

	questions chan question
	reports   chan proxy.Report
}

// startServeWAF starts a stand-in for servewaf.
func startServeWAF(t *testing.T, answer http.HandlerFunc) *serveWAF {
	t.Helper()

	s := &serveWAF{
		questions: make(chan question, 10),
		reports:   make(chan proxy.Report, 10),
	}
	s.Server = httptest.NewServer(http.HandlerFunc(
		func(w http.ResponseWriter, r *http.Request) {
			if r.Header.Get(proxy.ClientHeader) == "" {
				s.takeReport(t, w, r)

				return
			}

			body, err := io.ReadAll(r.Body)
			if err != nil {
				t.Errorf("read the question's body: %v", err)
			}

			s.questions <- question{
				r.Method, r.RequestURI, r.Host, r.Header.Clone(), body, r.ContentLength,
				r.TransferEncoding,
			}

			answer(w, r)
		}))
	t.Cleanup(s.Close)

	return s
}

// takeReport keeps a report and answers it as servewaf does.
func (s *serveWAF) takeReport(t *testing.T, w http.ResponseWriter, r *http.Request) {
	t.Helper()

	var report proxy.Report

	err := json.NewDecoder(r.Body).Decode(&report)
	if err != nil || r.Method != http.MethodPost || r.URL.Path != proxy.ReportPath {
		t.Errorf("%s %s is no report: %v", r.Method, r.URL.Path, err)
	}

	w.WriteHeader(http.StatusNoContent)

	s.reports <- report
}

// wantNoReport checks that no report comes for a moment.
func (s *serveWAF) wantNoReport(t *testing.T) {
	t.Helper()

	select {
	case report := <-s.reports:
		t.Errorf("report %+v, want none", report)
	case <-time.After(10 * pollInterval):
	}
}

// report waits for a report.
func (s *serveWAF) report(t *testing.T) proxy.Report {
	t.Helper()

	select {
	case report := <-s.reports:
		return report
	case <-time.After(waitLimit):
		t.Fatal("no report")

		return proxy.Report{}
	}
}

// question waits for a question.
func (s *serveWAF) question(t *testing.T) question {
	t.Helper()

	select {
	case asked := <-s.questions:
		return asked
	case <-time.After(waitLimit):
		t.Fatal("no question")

		return question{}
	}
}

// allow answers a question with allow.
func allow(w http.ResponseWriter, _ *http.Request) {
	w.Header().Set(dispositionHeader, dispositionAllow)
	w.WriteHeader(http.StatusOK)
}

// deny answers a question with deny, status 403 and a body of its own.
func deny(w http.ResponseWriter, _ *http.Request) {
	w.Header().Set(dispositionHeader, dispositionDeny)
	w.Header().Set(fromServeWAFHeader, "yes")
	w.WriteHeader(http.StatusForbidden)
	_, _ = io.WriteString(w, deniedBody)
}

// startApp starts app as the app rproxy passes requests to.
func startApp(t *testing.T, app http.HandlerFunc) *httptest.Server {
	t.Helper()

	server := httptest.NewServer(app)
	t.Cleanup(server.Close)

	return server
}

// greet is an app that reads the request's body and answers greeting.
func greet(w http.ResponseWriter, r *http.Request) {
	_, _ = io.Copy(io.Discard, r.Body)
	_, _ = io.WriteString(w, greeting)
}

// startRProxy starts rproxy with servewaf at backend and the app at appURL, and
// the settings in env on top of the defaults. It returns where rproxy listens
// and what it writes.
func startRProxy(
	t *testing.T, backend, appURL string, env map[string]string,
) (string, *output) {
	t.Helper()

	addr, out, _ := startServer(t, backend, appURL, env)

	return addr, out
}

// startServer is startRProxy, and returns the server as well.
func startServer(
	t *testing.T, backend, appURL string, env map[string]string,
) (string, *output, *rproxy.Server) {
	t.Helper()

	settings := map[string]string{
		"SWRP_WAF_BACKEND": backend, "SWRP_UPSTREAM_URL": appURL,
	}
	maps.Copy(settings, env)

	cfg, err := config.RProxyFromEnvironment(func(name string) (string, bool) {
		value, ok := settings[name]

		return value, ok
	})
	if err != nil {
		t.Fatalf("settings %v: %v", settings, err)
	}

	out := &output{}
	server := rproxy.New(rproxy.Params{
		Config:     cfg,
		RequestLog: out,
		ProcessLog: requestlog.NewProcessLogger(out, "test", slog.LevelInfo),
	})

	listener, err := (&net.ListenConfig{}).Listen(t.Context(), "tcp", localhost+":0")
	if err != nil {
		t.Fatalf("listen: %v", err)
	}

	go func() {
		_ = server.Serve(listener)
	}()

	t.Cleanup(func() {
		_ = server.Close()

		server.WaitForReports()
	})

	return listener.Addr().String(), out, server
}

// answered is the visitor's answer.
type answered struct {
	status int
	header http.Header
	body   string
}

// visit sends req as a visitor, on a connection of its own, and returns the
// answer.
func visit(t *testing.T, req *http.Request) answered {
	t.Helper()

	transport := &http.Transport{DisableKeepAlives: true, DisableCompression: true}
	defer transport.CloseIdleConnections()

	res, err := transport.RoundTrip(req)
	if err != nil {
		t.Fatalf("request: %v", err)
	}

	defer func() {
		_ = res.Body.Close()
	}()

	body, err := io.ReadAll(res.Body)
	if err != nil {
		t.Fatalf("read the answer: %v", err)
	}

	return answered{res.StatusCode, res.Header, string(body)}
}

// newRequest returns a request for target at addr.
func newRequest(
	t *testing.T, method, addr, target string, body io.Reader,
) *http.Request {
	t.Helper()

	req, err := http.NewRequestWithContext(t.Context(), method, "http://"+addr+target,
		body)
	if err != nil {
		t.Fatalf("new request: %v", err)
	}

	return req
}

// get sends a GET for target at addr, and returns the answer.
func get(t *testing.T, addr, target string) answered {
	t.Helper()

	return visit(t, newRequest(t, http.MethodGet, addr, target, http.NoBody))
}

// wantGreeting checks that the answer is the app's.
func wantGreeting(t *testing.T, got answered) {
	t.Helper()

	if got.status != http.StatusOK || got.body != greeting {
		t.Errorf("answered %d %q, want the app's greeting", got.status, got.body)
	}
}

// dial opens a connection to addr, closed as the test ends.
func dial(t *testing.T, addr string) net.Conn {
	t.Helper()

	conn, err := (&net.Dialer{}).DialContext(t.Context(), "tcp", addr)
	if err != nil {
		t.Fatalf("dial: %v", err)
	}

	t.Cleanup(func() {
		_ = conn.Close()
	})

	err = conn.SetDeadline(time.Now().Add(waitLimit))
	if err != nil {
		t.Fatalf("set the deadline: %v", err)
	}

	return conn
}

// send writes text to conn.
func send(t *testing.T, conn net.Conn, text string) {
	t.Helper()

	_, err := io.WriteString(conn, text)
	if err != nil {
		t.Fatalf("send: %v", err)
	}
}

// readStatus reads the answer's status from conn.
func readStatus(t *testing.T, conn net.Conn) int {
	t.Helper()

	res, err := http.ReadResponse(bufio.NewReader(conn), nil)
	if err != nil {
		t.Fatalf("read the answer: %v", err)
	}

	_ = res.Body.Close()

	return res.StatusCode
}

func TestPassesAnAllowedRequestToTheAppAndItsAnswerBack(t *testing.T) {
	t.Parallel()

	servewaf := startServeWAF(t, func(w http.ResponseWriter, r *http.Request) {
		w.Header().Set(asnHeader, "AS64496")
		w.Header().Set(countryHeader, "DE")
		allow(w, r)
	})

	seen := make(chan *http.Request, 1)
	app := startApp(t, func(w http.ResponseWriter, r *http.Request) {
		seen <- r.Clone(t.Context())

		w.Header().Set("X-App", "yes")
		w.WriteHeader(http.StatusTeapot)
		_, _ = io.WriteString(w, greeting)
	})
	addr, _ := startRProxy(t, servewaf.URL, app.URL, nil)

	const target = "/some%2Fpath/with%20space?b=2&a=1&bad=%zz;x"

	req := newRequest(t, http.MethodGet, addr, target, http.NoBody)
	req.Host = site
	req.Header.Set(asnHeader, "AS1")
	req.Header.Set(countryHeader, "XX")
	req.Header.Set(requestIDHeader, "the-visitor's")

	got := visit(t, req)
	if got.status != http.StatusTeapot || got.body != greeting ||
		got.header.Get("X-App") != "yes" {
		t.Errorf("answered %+v, want the app's answer", got)
	}

	received := <-seen
	asked := servewaf.question(t)

	if received.RequestURI != target || received.Host != site {
		t.Errorf("the app saw %s for %s", received.RequestURI, received.Host)
	}

	for name, want := range map[string]string{
		asnHeader:          "AS64496",
		countryHeader:      "DE",
		forwardedForHeader: localhost,
		requestIDHeader:    asked.header.Get(requestIDHeader),
	} {
		if received.Header.Get(name) != want {
			t.Errorf("the app saw %s %q, want %q", name, received.Header.Get(name), want)
		}
	}
}

func TestRemovesTheVisitorsLookupHeadersWhenServeWAFGivesNone(t *testing.T) {
	t.Parallel()

	for _, tc := range []struct {
		name    string
		backend func(t *testing.T) string
	}{
		{"servewaf allows", func(t *testing.T) string {
			t.Helper()

			return startServeWAF(t, allow).URL
		}},
		{"servewaf is down", func(*testing.T) string { return nowhere }},
	} {
		t.Run(tc.name, func(t *testing.T) {
			t.Parallel()

			seen := make(chan http.Header, 1)
			app := startApp(t, func(w http.ResponseWriter, r *http.Request) {
				seen <- r.Header.Clone()

				greet(w, r)
			})
			addr, _ := startRProxy(t, tc.backend(t), app.URL, nil)

			req := newRequest(t, http.MethodGet, addr, "/", http.NoBody)
			req.Header.Set(asnHeader, "AS1")
			req.Header.Set(countryHeader, "XX")
			wantGreeting(t, visit(t, req))

			header := <-seen
			if len(header.Values(asnHeader)) != 0 || len(header.Values(countryHeader)) != 0 {
				t.Errorf("the app saw the visitor's lookup headers: %v", header)
			}
		})
	}
}

func TestDenyGivesTheVisitorServeWAFsAnswer(t *testing.T) {
	t.Parallel()

	servewaf := startServeWAF(t, deny)
	app := startApp(t, func(http.ResponseWriter, *http.Request) {
		t.Error("the app was asked")
	})
	addr, out := startRProxy(t, servewaf.URL, app.URL, nil)

	got := get(t, addr, "/")
	if got.status != http.StatusForbidden || got.body != deniedBody ||
		got.header.Get(fromServeWAFHeader) != "yes" {
		t.Errorf("answered %+v, want servewaf's answer", got)
	}

	if len(got.header.Values(dispositionHeader)) != 0 {
		t.Errorf("the visitor got %s", dispositionHeader)
	}

	report := servewaf.report(t)
	if report.Status != http.StatusForbidden ||
		report.ResponseBytes != int64(len(deniedBody)) ||
		report.DurationUpstreamTotal != 0 {
		t.Errorf("report %+v, of a request denied", report)
	}

	line := out.requestLine(t)
	if line["disposition"] != dispositionDeny || line["default_disposition"] != nil {
		t.Errorf("line %v, want servewaf's deny", line)
	}
}

func TestCloseClosesTheConnectionWithoutAnAnswer(t *testing.T) {
	t.Parallel()

	servewaf := startServeWAF(t, func(w http.ResponseWriter, _ *http.Request) {
		w.Header().Set(dispositionHeader, dispositionClose)
		w.WriteHeader(http.StatusOK)
	})
	app := startApp(t, func(http.ResponseWriter, *http.Request) {
		t.Error("the app was asked")
	})
	addr, out := startRProxy(t, servewaf.URL, app.URL, nil)

	conn := dial(t, addr)
	send(t, conn, "GET / HTTP/1.1\r\nHost: site.example\r\n\r\n")

	text, err := io.ReadAll(conn)
	if err != nil || len(text) != 0 {
		t.Errorf("read %q (%v), want the connection closed without an answer",
			text, err)
	}

	report := servewaf.report(t)
	if report.Status != 0 || report.ResponseBytes != 0 {
		t.Errorf("report %+v, of a visitor sent nothing", report)
	}

	line := out.requestLine(t)
	if line["disposition"] != dispositionClose || line["status"] != 0.0 {
		t.Errorf("line %v, want close and status 0", line)
	}
}

// noAnswers are the ways servewaf can fail to give an answer that holds.
func noAnswers() map[string]func(t *testing.T) string {
	answeringWith := func(answer http.HandlerFunc) func(t *testing.T) string {
		return func(t *testing.T) string {
			t.Helper()

			return startServeWAF(t, answer).URL
		}
	}

	return map[string]func(t *testing.T) string{
		"down": func(*testing.T) string { return nowhere },
		"too slow": answeringWith(func(_ http.ResponseWriter, r *http.Request) {
			<-r.Context().Done()
		}),
		"no disposition": answeringWith(func(w http.ResponseWriter, _ *http.Request) {
			w.WriteHeader(http.StatusOK)
		}),
		"a question refused": answeringWith(func(w http.ResponseWriter, _ *http.Request) {
			http.Error(w, "refused", http.StatusBadRequest)
		}),
		"an unknown disposition": answeringWith(
			func(w http.ResponseWriter, _ *http.Request) {
				w.Header().Set(dispositionHeader, "maybe")
				w.WriteHeader(http.StatusOK)
			}),
		"an answer cut short": answeringWith(
			func(w http.ResponseWriter, _ *http.Request) {
				w.Header().Set(dispositionHeader, dispositionDeny)
				w.Header().Set(contentLengthHeader, "100")
				w.WriteHeader(http.StatusForbidden)
				_, _ = io.WriteString(w, deniedBody)

				panic(http.ErrAbortHandler)
			}),
		"an answer too long": answeringWith(func(w http.ResponseWriter, _ *http.Request) {
			w.Header().Set(dispositionHeader, dispositionDeny)
			w.WriteHeader(http.StatusForbidden)
			_, _ = w.Write(make([]byte, 1<<20+1))
		}),
	}
}

func TestWithoutAnAnswerTheDefaultDispositionDecides(t *testing.T) {
	t.Parallel()

	for name, backend := range noAnswers() {
		t.Run("fails open on "+name, func(t *testing.T) {
			t.Parallel()

			app := startApp(t, greet)
			addr, out := startRProxy(t, backend(t), app.URL, map[string]string{
				timeoutSetting: "200",
			})

			wantGreeting(t, get(t, addr, "/"))

			line := out.requestLine(t)
			if line["disposition"] != dispositionAllow ||
				line["default_disposition"] != true {
				t.Errorf("line %v, want allow by default", line)
			}
		})

		t.Run("fails closed on "+name, func(t *testing.T) {
			t.Parallel()

			app := startApp(t, func(http.ResponseWriter, *http.Request) {
				t.Error("the app was asked")
			})
			addr, out := startRProxy(t, backend(t), app.URL, map[string]string{
				timeoutSetting:     "200",
				defaultDisposition: dispositionDeny,
			})

			got := get(t, addr, "/")
			if got.status != http.StatusServiceUnavailable {
				t.Errorf("answered %+v, want 503", got)
			}

			line := out.requestLine(t)
			if line["disposition"] != dispositionDeny ||
				line["default_disposition"] != true {
				t.Errorf("line %v, want deny by default", line)
			}
		})
	}
}

func TestSendsNoReportWithoutAnAnswer(t *testing.T) {
	t.Parallel()

	servewaf := startServeWAF(t, func(w http.ResponseWriter, _ *http.Request) {
		http.Error(w, "refused", http.StatusBadRequest)
	})
	app := startApp(t, greet)
	addr, out := startRProxy(t, servewaf.URL, app.URL, nil)

	wantGreeting(t, get(t, addr, "/"))
	out.requestLine(t)
	servewaf.wantNoReport(t)
}

func TestAPathUnderOwnPrefixNeverReachesTheApp(t *testing.T) {
	t.Parallel()

	app := startApp(t, func(http.ResponseWriter, *http.Request) {
		t.Error("the app was asked")
	})
	addr, _ := startRProxy(t, nowhere, app.URL, nil)

	got := get(t, addr, "/_smallwebwaf/metrics")
	if got.status != http.StatusNotFound {
		t.Errorf("answered %+v, want 404", got)
	}
}

func TestHealthCheckIsAnsweredWhileServeWAFIsDown(t *testing.T) {
	t.Parallel()

	servewaf := startServeWAF(t, allow)
	app := startApp(t, greet)
	addr, out := startRProxy(t, nowhere, app.URL, nil)

	got := get(t, addr, proxy.HealthPath)
	if got.status != http.StatusOK || got.body != "ok\n" {
		t.Errorf("answered %+v, want ok", got)
	}

	line := out.requestLine(t)
	if line["path"] != proxy.HealthPath || line["disposition"] != nil {
		t.Errorf("line %v, want one with no disposition", line)
	}

	// With servewaf up too, it is not asked.
	addr, _ = startRProxy(t, servewaf.URL, app.URL, nil)
	get(t, addr, proxy.HealthPath)

	if len(servewaf.questions) != 0 {
		t.Error("servewaf was asked about the health check")
	}
}

func TestReportComesAfterTheAnswerWithoutTheVisitorWaiting(t *testing.T) {
	t.Parallel()

	release := make(chan struct{})
	reports := make(chan proxy.Report, 1)
	backend := httptest.NewServer(http.HandlerFunc(
		func(w http.ResponseWriter, r *http.Request) {
			if r.Header.Get(proxy.ClientHeader) != "" {
				allow(w, r)

				return
			}

			var report proxy.Report

			_ = json.NewDecoder(r.Body).Decode(&report)
			reports <- report

			select {
			case <-release:
			case <-r.Context().Done():
			}

			w.WriteHeader(http.StatusNoContent)
		}))
	t.Cleanup(backend.Close)

	const body = "the visitor's body"

	app := startApp(t, greet)
	addr, out := startRProxy(t, backend.URL, app.URL, nil)

	// The stand-in does not answer the report until the visitor has its answer.
	wantGreeting(t, visit(t, newRequest(t, http.MethodPost, addr, "/",
		strings.NewReader(body))))
	close(release)

	var report proxy.Report

	select {
	case report = <-reports:
	case <-time.After(waitLimit):
		t.Fatal("no report")
	}

	if report.RequestID == "" || report.Status != http.StatusOK ||
		report.RequestBytes != int64(len(body)) ||
		report.ResponseBytes != int64(len(greeting)) ||
		report.DurationTotal <= 0 || report.DurationUpstreamTotal <= 0 ||
		report.DurationUpstreamTotal > report.DurationTotal {
		t.Errorf("report %+v, of %d bytes up and %d back", report, len(body), len(greeting))
	}

	line := out.requestLine(t)
	if line["request_id"] != report.RequestID {
		t.Errorf("line %v, report %+v, want the same request id", line, report)
	}
}

func TestWaitForReportsWaitsForAReportBeingSent(t *testing.T) {
	t.Parallel()

	reportGotThere := make(chan struct{})
	release := make(chan struct{})
	backend := httptest.NewServer(http.HandlerFunc(
		func(w http.ResponseWriter, r *http.Request) {
			if r.Header.Get(proxy.ClientHeader) != "" {
				allow(w, r)

				return
			}

			close(reportGotThere)

			select {
			case <-release:
			case <-r.Context().Done():
			}

			w.WriteHeader(http.StatusNoContent)
		}))
	t.Cleanup(backend.Close)

	app := startApp(t, greet)
	addr, _, server := startServer(t, backend.URL, app.URL, map[string]string{
		timeoutSetting: "5000",
	})

	wantGreeting(t, get(t, addr, "/"))

	select {
	case <-reportGotThere:
	case <-time.After(waitLimit):
		t.Fatal("no report")
	}

	waited := make(chan struct{})

	go func() {
		server.WaitForReports()
		close(waited)
	}()

	select {
	case <-waited:
		t.Error("it did not wait for the report")
	case <-time.After(10 * pollInterval):
	}

	close(release)

	select {
	case <-waited:
	case <-time.After(waitLimit):
		t.Error("it still waits, the report having been answered")
	}
}

func TestReportOfAWebSocketCountsWhatItCarried(t *testing.T) {
	t.Parallel()

	servewaf := startServeWAF(t, allow)
	app := startApp(t, echoAfterUpgrade)
	addr, out := startRProxy(t, servewaf.URL, app.URL, map[string]string{
		maxRequestTime:  "2000",
		maxResponseTime: "2000",
	})

	conn := dial(t, addr)
	send(t, conn, "GET /socket HTTP/1.1\r\nHost: app\r\n"+
		"Connection: Upgrade\r\nUpgrade: websocket\r\n\r\n")

	reader := bufio.NewReader(conn)

	res, err := http.ReadResponse(reader, nil)
	if err != nil {
		t.Fatalf("read the answer to the upgrade: %v", err)
	}

	_ = res.Body.Close()

	if res.StatusCode != http.StatusSwitchingProtocols {
		t.Fatalf("status %d, want %d", res.StatusCode, http.StatusSwitchingProtocols)
	}

	// Past both time limits, the connection still carries what is sent.
	time.Sleep(2100 * time.Millisecond)

	const message = "still here\n"

	send(t, conn, message)

	echoed, err := reader.ReadString('\n')
	if err != nil || echoed != message {
		t.Errorf("echo %q (%v), want %q", echoed, err, message)
	}

	_ = conn.Close()

	report := servewaf.report(t)
	if report.Status != http.StatusSwitchingProtocols ||
		report.RequestBytes != int64(len(message)) ||
		report.ResponseBytes != int64(len(message)) {
		t.Errorf("report %+v, of %d bytes each way", report, len(message))
	}

	if line := out.requestLine(t); line["status"] != float64(res.StatusCode) {
		t.Errorf("line %v, want status 101", line)
	}
}

// echoAfterUpgrade is an app that switches protocols on request, and then sends
// back each line it receives.
func echoAfterUpgrade(w http.ResponseWriter, _ *http.Request) {
	conn, buffered, err := http.NewResponseController(w).Hijack()
	if err != nil {
		return
	}

	defer func() {
		_ = conn.Close()
	}()

	_, _ = buffered.WriteString("HTTP/1.1 101 Switching Protocols\r\n" +
		"Connection: Upgrade\r\nUpgrade: websocket\r\n\r\n")
	_ = buffered.Flush()

	for {
		line, err := buffered.ReadString('\n')
		if err != nil {
			return
		}

		_, _ = buffered.WriteString(line)
		_ = buffered.Flush()
	}
}

func TestEachRequestGetsAFreshID(t *testing.T) {
	t.Parallel()

	const fromTraefik = "an-id-from-traefik"

	servewaf := startServeWAF(t, allow)
	app := startApp(t, greet)
	addr, _ := startRProxy(t, servewaf.URL, app.URL, map[string]string{
		trustedProxies: localhost + "/32",
	})

	ids := make([]string, 0, 2)

	for range 2 {
		req := newRequest(t, http.MethodGet, addr, "/", http.NoBody)
		req.Header.Set(requestIDHeader, fromTraefik)
		wantGreeting(t, visit(t, req))

		ids = append(ids, servewaf.question(t).header.Get(requestIDHeader))
	}

	if slices.Contains(ids, fromTraefik) || ids[0] == "" || ids[0] == ids[1] {
		t.Errorf("ids %v, want two fresh ones", ids)
	}
}

func TestLogLineGivesTheRequestAsSent(t *testing.T) {
	t.Parallel()

	const (
		path  = "/search%2Fall"
		query = "q=secret&token=%zz"
		body  = "the visitor's body"
	)

	servewaf := startServeWAF(t, allow)
	app := startApp(t, greet)
	addr, out := startRProxy(t, servewaf.URL, app.URL, nil)

	req := newRequest(t, http.MethodPost, addr, path+"?"+query, strings.NewReader(body))
	req.Host = site
	wantGreeting(t, visit(t, req))

	line := out.requestLine(t)
	asked := servewaf.question(t)

	for name, want := range map[string]any{
		"type":           "request",
		"request_id":     asked.header.Get(requestIDHeader),
		"client_ip":      localhost,
		"host":           site,
		"method":         http.MethodPost,
		"path":           path,
		"query":          query,
		"status":         float64(http.StatusOK),
		"request_bytes":  float64(len(body)),
		"response_bytes": float64(len(greeting)),
		"disposition":    dispositionAllow,
	} {
		if line[name] != want {
			t.Errorf("%s is %v, want %v", name, line[name], want)
		}
	}

	if line["default_disposition"] != nil {
		t.Errorf("default_disposition is %v, want it left out", line["default_disposition"])
	}

	for _, name := range []string{"duration_request", "duration_response"} {
		duration, ok := line[name].(float64)
		if !ok || duration <= 0 {
			t.Errorf("%s is %v, want a time", name, line[name])
		}
	}

	text, _ := line["time"].(string)

	_, err := time.Parse(time.RFC3339, text)
	if err != nil {
		t.Errorf("time: %v", err)
	}
}