rproxy and servewaf replace the one-process smallwebwaf (closes #172, closes #165)

`smallwebwaf` with no command now prints the commands and exits with status 2.
The image runs rproxy, or servewaf with SMALLWEBWAF_COMMAND=servewaf. The
passing-on code, its settings and its log fields and metric go. internal/proxy
keeps the checks, answers, reports and own endpoints; its tests run through the
real rproxy. The documents describe the pair.

Judgement call: clients.json keeps token_refused, since state files refuse unknown fields.
Deviation: script/gitea-requests sets SWWAF_LOG_REQUEST_HEADERS, to label requests.

Model: opus-5-5

internal/proxy/requestlog_test.go

@@ -2,7 +2,6 @@ package proxy_test
 
 import (
 	"io"
-	"maps"
 	"math"
 	"net/http"
 	"reflect"
@@ -42,9 +41,6 @@ func TestLogLineHasEachFieldWhereItApplies(t *testing.T) {
 			return
 		}
 
-		w.Header().Set("Content-Type", "text/html")
-		w.Header().Set("Cache-Control", "no-store")
-		w.Header().Set("Location", "/elsewhere")
 		w.WriteHeader(http.StatusFound)
 		_, _ = io.WriteString(w, "moved")
 	})
@@ -70,7 +66,7 @@ func TestLogLineHasEachFieldWhereItApplies(t *testing.T) {
 
 	// A request's log line can come after its answer: each is waited for
 	// before the next request, so that the lines are in order.
-	full := out.requestLines(t, 1)[0]
+	full := out.endedLines(t, 1)[0]
 
 	// This one comes from 127.0.0.1, which the rate limits do not count,
 	// with a body of 4 bytes whose length it does not announce, so that its
@@ -81,7 +77,7 @@ func TestLogLineHasEachFieldWhereItApplies(t *testing.T) {
 		"Transfer-Encoding: chunked\r\n\r\n4\r\nbody\r\n0\r\n\r\n")
 	wantStatus(t, readResponse(t, conn), http.StatusNoContent)
 
-	bare := out.requestLines(t, 2)[1]
+	bare := out.endedLines(t, 2)[1]
 
 	wantFullLine(t, full)
 	wantBareLine(t, bare)
@@ -108,24 +104,23 @@ func wantFullLine(t *testing.T, line logLine) {
 	headers := map[string]string{"accept": "text/html", "x-custom": "one, two"}
 
 	want := withTimings(line, requestlog.Line{
-		Type: requestType, Time: line.Time, Instance: instance,
+		Type: requestType, ServeWAFLine: requestlog.ServeWAFLineReport,
+		Time: line.Time, Instance: instance,
 		ClientIP: ipv6Client, Method: http.MethodPost, Scheme: secure,
 		Host: appHost, Path: "/full", Protocol: protocol,
 		Status: http.StatusFound, RequestBytes: 3, ResponseBytes: 5,
-		RequestID: "from-traefik", PeerIP: localhost,
+		RequestID: line.RequestID, PeerIP: localhost,
 		ForwardedFor: "198.51.100.7, " + ipv6Client, ClientGroup: ipv6Group,
 		ContentType: "application/x-www-form-urlencoded", ContentLength: 3,
 		RequestHeaders: headers, HasAuthorization: true, HasCookie: true,
-		ResponseContentType: "text/html", UpstreamStatus: http.StatusFound,
-		CacheControl: "no-store", Location: "/elsewhere",
 		Action: requestlog.ActionForward,
 		// Its 3 bytes in and 5 out, each way counted by default.
 		Counts: ratelimit.Counts{
 			Minute: 1, Hour: 1, Day: 1, MinuteBytes: 8, HourBytes: 8, DayBytes: 8,
 		},
 	})
-	if !reflect.DeepEqual(line.Line, want) {
-		t.Errorf("log line\n%+v\nwant\n%+v", line.Line, want)
+	if !reflect.DeepEqual(line.Line, want) || line.RequestID == "from-traefik" {
+		t.Errorf("log line\n%+v\nwant\n%+v, with a new request id", line.Line, want)
 	}
 }
 
@@ -135,12 +130,13 @@ func wantBareLine(t *testing.T, line logLine) {
 	t.Helper()
 
 	want := withTimings(line, requestlog.Line{
-		Type: requestType, Time: line.Time, Instance: instance,
+		Type: requestType, ServeWAFLine: requestlog.ServeWAFLineReport,
+		Time: line.Time, Instance: instance,
 		ClientIP: localhost, Method: http.MethodPost, Scheme: plain,
 		Host: appHost, Path: "/bare", Protocol: protocol,
 		Status: http.StatusNoContent, RequestBytes: 4, RequestID: line.RequestID,
 		PeerIP: localhost, ClientGroup: localhost + "/32",
-		UpstreamStatus: http.StatusNoContent, Action: requestlog.ActionForward,
+		Action: requestlog.ActionForward,
 	})
 	if !reflect.DeepEqual(line.Line, want) || line.RequestID == "" {
 		t.Errorf("log line\n%+v\nwant\n%+v, with a request id", line.Line, want)
@@ -148,8 +144,7 @@ func wantBareLine(t *testing.T, line logLine) {
 
 	for _, name := range []string{
 		"forwarded_for", "content_type", "content_length", "request_headers",
-		"has_authorization", "has_cookie", "websocket", "response_content_type",
-		"cache_control", "location", "counts",
+		"has_authorization", "has_cookie", "response_content_type", "counts",
 	} {
 		_, present := line.fields[name]
 		if present {
@@ -162,8 +157,6 @@ func wantBareLine(t *testing.T, line logLine) {
 func withTimings(line logLine, want requestlog.Line) requestlog.Line {
 	want.DurationTotal = line.DurationTotal
 	want.DurationChecks = line.DurationChecks
-	want.DurationUpstreamConnect = line.DurationUpstreamConnect
-	want.DurationUpstreamFirstByte = line.DurationUpstreamFirstByte
 	want.DurationUpstreamTotal = line.DurationUpstreamTotal
 
 	return want
@@ -188,7 +181,7 @@ func TestHasAuthorizationAndHasCookieEachComeFromTheirOwnHeader(t *testing.T) {
 			req.Header.Set(tc.header, "secret")
 			wantStatus(t, do(t, req), http.StatusOK)
 
-			line := out.requestLine(t)
+			line := out.endedLine(t)
 
 			_, otherPresent := line.fields[tc.other]
 			if line.fields[tc.field] != true || otherPresent {
@@ -199,81 +192,20 @@ func TestHasAuthorizationAndHasCookieEachComeFromTheirOwnHeader(t *testing.T) {
 	}
 }
 
-func TestRequestIDAndSchemeComeOnlyFromATrustedProxy(t *testing.T) {
-	t.Parallel()
-
-	const sentID = "from-traefik"
-
-	sent := http.Header{requestIDHeader: {sentID}, forwardedProto: {secure}}
-	trusted := map[string]string{trustedProxies: trustLocalhost}
-
-	for _, tc := range []struct {
-		name   string
-		env    map[string]string
-		header http.Header
-		// wantID is the request id logged, "" for a new one.
-		wantID, wantScheme string
-	}{
-		{"a trusted proxy's are kept", trusted, sent, sentID, secure},
-		{"without them, the id is new and the scheme http", trusted, nil, "", plain},
-		{"another peer's are replaced", nil, sent, "", plain},
-	} {
-		t.Run(tc.name, func(t *testing.T) {
-			t.Parallel()
-
-			received := make(chan string, 2)
-			app := startApp(t, func(_ http.ResponseWriter, r *http.Request) {
-				received <- r.Header.Get(requestIDHeader)
-			})
-			addr, out := startProxy(t, app.URL, tc.env)
-
-			// Two requests, so that two new ids can be told apart.
-			ids := make([]string, 0, 2)
-
-			for i := range 2 {
-				req := newRequest(t, http.MethodGet, addr, "/", http.NoBody)
-				maps.Copy(req.Header, tc.header)
-				wantStatus(t, do(t, req), http.StatusOK)
-
-				line := out.requestLines(t, i+1)[i]
-				ids = append(ids, line.RequestID)
-
-				got := <-received
-				if line.RequestID != got || line.Scheme != tc.wantScheme {
-					t.Errorf("log line has request_id %q and scheme %q, and the "+
-						"app received id %q; want the same id and scheme %q",
-						line.RequestID, line.Scheme, got, tc.wantScheme)
-				}
-			}
-
-			switch {
-			case tc.wantID != "" && (ids[0] != tc.wantID || ids[1] != tc.wantID):
-				t.Errorf("request ids %q, want %q", ids, tc.wantID)
-			case tc.wantID == "" && (slices.Contains(ids, sentID) ||
-				slices.Contains(ids, "") || ids[0] == ids[1]):
-				t.Errorf("request ids %q, want two new ones", ids)
-			}
-		})
-	}
-}
-
 func TestTimingsAreInOrder(t *testing.T) {
 	t.Parallel()
 
 	const denied = "192.0.2.50" // in SWWAF_DENY_NETS
 
 	app := startApp(t, func(w http.ResponseWriter, _ *http.Request) {
-		// The pauses set the times apart; a hold-up of the test only
-		// lengthens them.
-		time.Sleep(time.Millisecond)
-		w.WriteHeader(http.StatusOK)
-		_ = http.NewResponseController(w).Flush()
-
+		// The pause sets the times apart; a hold-up of the test only lengthens
+		// it.
 		time.Sleep(time.Millisecond)
 
 		_, _ = io.WriteString(w, "done")
 	})
-	addr, out := startProxy(t, app.URL, map[string]string{
+
+	addr, out, server := startProxyWithClock(t, app.URL, "", time.Now, map[string]string{
 		trustedProxies: trustLocalhost,
 		denyNets:       denied,
 	})
@@ -281,20 +213,19 @@ func TestTimingsAreInOrder(t *testing.T) {
 	// Each log line is waited for before the next request, so that the
 	// lines are in order.
 	wantStatus(t, get(t, addr, "/"), http.StatusOK)
-	forwarded := out.requestLines(t, 1)[0]
+	forwarded := out.endedLines(t, 1)[0]
 
 	req := newRequest(t, http.MethodGet, addr, "/", http.NoBody)
 	req.Header.Set(forwardedFor, denied)
 	wantStatus(t, do(t, req), http.StatusForbidden)
-	refused := out.requestLines(t, 2)[1]
+	refused := out.endedLines(t, 2)[1]
 
-	wantStatus(t, get(t, addr, proxy.HealthPath), http.StatusOK)
-	health := out.requestLines(t, 3)[2]
+	wantStatus(t, get(t, server.Addr, proxy.HealthPath), http.StatusOK)
+	health := out.endedLines(t, 3)[2]
 
 	// A request passed to the app has every timing; one refused, none of
 	// the app's; the health check, which runs no check, only the total.
 	wantTimings(t, forwarded, "duration_total", "duration_checks",
-		"duration_upstream_connect", "duration_upstream_first_byte",
 		"duration_upstream_total")
 	wantTimings(t, refused, "duration_total", "duration_checks")
 	wantTimings(t, health, "duration_total")
@@ -307,17 +238,12 @@ func TestTimingsAreInOrder(t *testing.T) {
 	// exact.
 	total := microseconds(forwarded.DurationTotal)
 	checks := microseconds(*forwarded.DurationChecks)
-	connect := microseconds(*forwarded.DurationUpstreamConnect)
-	firstByte := microseconds(*forwarded.DurationUpstreamFirstByte)
 	upstream := microseconds(*forwarded.DurationUpstreamTotal)
 
-	// The checks end before the request is handed to the app, and the
-	// connection comes before the answer, which the app ends after a
-	// pause.
-	if checks+upstream > total || connect >= firstByte || firstByte >= upstream {
-		t.Errorf("timings in microseconds: total %d, checks %d, connect %d, "+
-			"first byte %d, upstream total %d", total, checks, connect, firstByte,
-			upstream)
+	// The checks end before the request is handed to the app.
+	if checks+upstream > total {
+		t.Errorf("timings in microseconds: total %d, checks %d, upstream total %d",
+			total, checks, upstream)
 	}
 
 	if *refused.DurationChecks > refused.DurationTotal {
@@ -350,22 +276,3 @@ func wantTimings(t *testing.T, line logLine, want ...string) {
 func microseconds(milliseconds float64) int64 {
 	return int64(math.Round(milliseconds * 1000))
 }
-
-func TestLogsAnUpgradedConnection(t *testing.T) {
-	t.Parallel()
-
-	app := startApp(t, echoAfterUpgrade)
-	addr, out := startProxy(t, app.URL, nil)
-
-	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")
-	wantStatus(t, readResponse(t, conn), http.StatusSwitchingProtocols)
-
-	_ = conn.Close()
-
-	line := out.requestLine(t)
-	if line.fields["websocket"] != true {
-		t.Errorf("log line has websocket %v, want true", line.fields["websocket"])
-	}
-}