smallwebwaf/internal/servewaf/requestlog_test.go

package servewaf_test

import (
	"encoding/json"
	"io"
	"math"
	"net/http"
	"reflect"
	"slices"
	"strings"
	"testing"
	"time"

	"sneak.berlin/go/smallwebwaf/internal/ratelimit"
	"sneak.berlin/go/smallwebwaf/internal/requestlog"
	"sneak.berlin/go/smallwebwaf/internal/servewaf"
)

const (
	// requestIDHeader carries the request's id.
	requestIDHeader = "X-Request-ID"
	// instance is the SWWAF_INSTANCE_NAME a test sets.
	instance = "fsn1app1/gitea"
	// ipv6Client is a client on IPv6, and ipv6Group the netblock the rate
	// limits count it as.
	ipv6Client = "2001:db8::7"
	ipv6Group  = "2001:db8::/64"
)

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

	received := make(chan string, 2) // the request ids the app received
	app := startApp(t, func(w http.ResponseWriter, r *http.Request) {
		received <- r.Header.Get(requestIDHeader)

		_, _ = io.Copy(io.Discard, r.Body)

		if r.URL.Path != "/full" {
			w.WriteHeader(http.StatusNoContent)

			return
		}

		w.WriteHeader(http.StatusFound)
		_, _ = io.WriteString(w, "moved")
	})
	addr, out := startProxy(t, app.URL, map[string]string{
		trustedProxies:      trustLocalhost,
		rateLimitExemptNets: localhost,
		instanceName:        instance,
		logRequestHeaders:   "Accept,x-custom,Authorization,cookie,SET-COOKIE",
	})

	// This request comes from ipv6Client through a trusted proxy, with a
	// body and each header the log line looks at, and is answered with a
	// redirect.
	conn := dial(t, addr)
	send(t, conn, "POST /full HTTP/1.1\r\nHost: "+appHost+"\r\n"+
		forwardedFor+": 198.51.100.7, "+ipv6Client+"\r\n"+
		forwardedProto+": "+secure+"\r\n"+requestIDHeader+": from-traefik\r\n"+
		"Content-Type: application/x-www-form-urlencoded\r\nContent-Length: 3\r\n"+
		"Accept: text/html\r\nX-Custom: one\r\nX-Custom: two\r\n"+
		"Authorization: Bearer secret-token\r\nCookie: session=secret-cookie\r\n"+
		"Set-Cookie: secret-set-cookie\r\n\r\na=b")
	wantStatus(t, readResponse(t, conn), http.StatusFound)

	// 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.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
	// request_bytes is not its content_length, and no header the log line
	// looks at, and is answered with 204 and no header.
	conn = dial(t, addr)
	send(t, conn, "POST /bare HTTP/1.1\r\nHost: "+appHost+"\r\n"+
		"Transfer-Encoding: chunked\r\n\r\n4\r\nbody\r\n0\r\n\r\n")
	wantStatus(t, readResponse(t, conn), http.StatusNoContent)

	bare := out.endedLines(t, 2)[1]

	wantFullLine(t, full)
	wantBareLine(t, bare)

	for _, line := range []logLine{full, bare} {
		got := <-received
		if got != line.RequestID {
			t.Errorf("the app received request id %q, the log line has %q",
				got, line.RequestID)
		}
	}

	if strings.Contains(out.text(), "secret") {
		t.Errorf("a value of Authorization, Cookie or Set-Cookie is logged:\n%s",
			out.text())
	}
}

// wantFullLine checks the log line of the request with every header the
// line looks at. Its timings are checked by TestTimingsAreInOrder.
func wantFullLine(t *testing.T, line logLine) {
	t.Helper()

	headers := map[string]string{"accept": "text/html", "x-custom": "one, two"}

	want := withTimings(line, requestlog.Line{
		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: 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,
		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) || line.RequestID == "from-traefik" {
		t.Errorf("log line\n%+v\nwant\n%+v, with a new request id", line.Line, want)
	}
}

// wantBareLine checks the log line of the request with none of them, and
// that the fields that do not apply to it are left out.
func wantBareLine(t *testing.T, line logLine) {
	t.Helper()

	want := withTimings(line, requestlog.Line{
		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",
		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)
	}

	for _, name := range []string{
		"forwarded_for", "content_type", "content_length", "request_headers",
		"has_authorization", "has_cookie", "response_content_type", "counts",
	} {
		_, present := line.fields[name]
		if present {
			t.Errorf("log line has %s, which does not apply", name)
		}
	}
}

// withTimings returns want with the timings of line.
func withTimings(line logLine, want requestlog.Line) requestlog.Line {
	want.DurationTotal = line.DurationTotal
	want.DurationChecks = line.DurationChecks
	want.DurationUpstreamTotal = line.DurationUpstreamTotal

	return want
}

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

	const hasAuthorization, hasCookie = "has_authorization", "has_cookie"

	for _, tc := range []struct{ header, field, other string }{
		{"Authorization", hasAuthorization, hasCookie},
		{"Cookie", hasCookie, hasAuthorization},
	} {
		t.Run("only "+tc.header, func(t *testing.T) {
			t.Parallel()

			app := startApp(t, func(http.ResponseWriter, *http.Request) {})
			addr, out := startProxy(t, app.URL, nil)

			req := newRequest(t, http.MethodGet, addr, "/", http.NoBody)
			req.Header.Set(tc.header, "secret")
			wantStatus(t, do(t, req), http.StatusOK)

			line := out.endedLine(t)

			_, otherPresent := line.fields[tc.other]
			if line.fields[tc.field] != true || otherPresent {
				t.Errorf("log line has %s %v and %s %v, want true and none",
					tc.field, line.fields[tc.field], tc.other, line.fields[tc.other])
			}
		})
	}
}

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 pause sets the times apart; a hold-up of the test only lengthens
		// it.
		time.Sleep(time.Millisecond)

		_, _ = io.WriteString(w, "done")
	})

	addr, out, server := startProxyWithClock(t, app.URL, "", time.Now, map[string]string{
		trustedProxies: trustLocalhost,
		denyNets:       denied,
	})

	// 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.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.endedLines(t, 2)[1]

	wantStatus(t, get(t, server.Addr, servewaf.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_total")
	wantTimings(t, refused, "duration_total", "duration_checks")
	wantTimings(t, health, "duration_total")

	if t.Failed() {
		return
	}

	// In whole microseconds, as they are logged, so that the sum below is
	// exact.
	total := microseconds(forwarded.DurationTotal)
	checks := microseconds(*forwarded.DurationChecks)
	upstream := microseconds(*forwarded.DurationUpstreamTotal)

	// 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 {
		t.Errorf("refused request's checks took %v of %v milliseconds",
			*refused.DurationChecks, refused.DurationTotal)
	}
}

// wantTimings checks that the timings named are the only ones line has.
func wantTimings(t *testing.T, line logLine, want ...string) {
	t.Helper()

	var got []string

	for name := range line.fields {
		if strings.HasPrefix(name, "duration_") {
			got = append(got, name)
		}
	}

	slices.Sort(got)
	slices.Sort(want)

	if !slices.Equal(got, want) {
		t.Errorf("log line of %s has timings %v, want %v", line.Path, got, want)
	}
}

// wantHeuristic checks that line names heuristic as the one that refused the
// request, with figures, a JSON object. A heuristic of "" with figures "null" is
// a line that names none.
func wantHeuristic(t *testing.T, line logLine, heuristic, figures string) {
	t.Helper()

	if line.Heuristic != heuristic ||
		!reflect.DeepEqual(line.HeuristicFigures, decodeFigures(t, figures)) {
		t.Errorf("log line has heuristic %q with heuristic_figures %v, want %q with %s",
			line.Heuristic, line.HeuristicFigures, heuristic, figures)
	}
}

// wantAfterAnswerHeuristic checks after_answer_heuristic and
// after_answer_heuristic_figures as wantHeuristic checks heuristic and
// heuristic_figures.
func wantAfterAnswerHeuristic(t *testing.T, line logLine, heuristic, figures string) {
	t.Helper()

	if line.AfterAnswerHeuristic != heuristic ||
		!reflect.DeepEqual(line.AfterAnswerHeuristicFigures, decodeFigures(t, figures)) {
		t.Errorf("log line has after_answer_heuristic %q with "+
			"after_answer_heuristic_figures %v, want %q with %s",
			line.AfterAnswerHeuristic, line.AfterAnswerHeuristicFigures, heuristic, figures)
	}
}

// decodeFigures decodes figures, a JSON object of a heuristic's figures, as
// the log line's figures are decoded.
func decodeFigures(t *testing.T, figures string) map[string]any {
	t.Helper()

	var decoded map[string]any

	err := json.Unmarshal([]byte(figures), &decoded)
	if err != nil {
		t.Fatalf("decode %s: %v", figures, err)
	}

	return decoded
}

// microseconds is a timing in whole microseconds.
func microseconds(milliseconds float64) int64 {
	return int64(math.Round(milliseconds * 1000))
}