rproxy: close the connection when a short answer is cut off (closes #318)

When SWRP_MAX_RESPONSE_TIME_MS ran out before the last of a short answer
was written, the flush failed. If the visitor had stopped short of its
announced body, Go's server then read the rest until
SWRP_MAX_REQUEST_TIME_MS ran out, keeping the connection open with the
answer cut off.

finish now flushes once more, and if that fails at its deadline, it ends
the reading of the body at once. ReverseProxy ignores the failed flush when
the app's answer came in one read, and panics when it was still waiting for
more; finish runs after both. Go's server never reuses a connection after a
failed write, so it closes it.

Model: opus-5-5

AGENTS.md

@@ -37,3 +37,6 @@ These are the rules for agents working on this repository.
         - `192.168.0.0/16`.
     - `SPEC.md` states that default.
     - Forwarded headers count only when the peer is a trusted proxy.
+- Every time is in UTC, whatever `TZ` or the host's time zone says.
+    - Every day is a date written `YYYY-MM-DD`, never a time.
+    - `SPEC.md` states this near its start.

SPEC.md

@@ -12,6 +12,10 @@ it is built, except what the last section lists. `README.md` says how to run it.
 under `docs/` give the settings, the formats and the lists. This document links
 to them.
 
+The whole application stores, logs and handles every time in UTC, whatever `TZ`
+or the host's time zone says. It keeps every day as a date written `YYYY-MM-DD`,
+never as a time.
+
 ## Purpose
 
 - It protects self-hosted apps on the open internet from scrapers, scanners and
@@ -1775,6 +1779,7 @@ in. `docs/state-files.md` lists the files, what each holds, and their sizes.
     - a top-level `version` number;
     - entries sorted by client address;
     - times in RFC 3339 UTC;
+    - days as `YYYY-MM-DD`;
     - durations and sizes as plain numbers, with the unit in the field name.
 - `bans.json`, `reputation.json` and `alerts.json` are indented, so that a
   person can open `bans.json` in an editor, find an address, and remove or add

go.mod

@@ -3,6 +3,7 @@ module sneak.berlin/go/smallwebwaf
 go 1.26.0
 
 require (
+	cloud.google.com/go v0.123.0
 	github.com/corazawaf/coraza-coreruleset/v4 v4.25.0
 	github.com/corazawaf/coraza/v3 v3.8.2-0.20261022102553-d028be399c68
 	github.com/fsnotify/fsnotify v1.10.1

go.sum

@@ -1,3 +1,5 @@
+cloud.google.com/go v0.123.0 h1:2NAUJwPR47q+E35uaJeYoNhuNEM9kM8SjgRgdeOJUSE=
+cloud.google.com/go v0.123.0/go.mod h1:xBoMV08QcqUGuPW65Qfm1o9Y4zKZBpGS+7bImXLTAZU=
 github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM=
 github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw=
 github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs=

internal/lookup/file.go

@@ -26,7 +26,7 @@ type FileParams struct {
 	// Path is the lookup database, the IPinfo Lite file in its .mmdb form
 	// (SWW_LOOKUP_DB_PATH).
 	Path string
-	// Now tells the time, normally time.Now.
+	// Now tells the time, normally time.Now in UTC.
 	Now func() time.Time
 	// ProcessLog receives each reading of the file, and why a replacement
 	// of it cannot be read.

internal/lookup/lookup.go

@@ -74,7 +74,7 @@ type Params struct {
 	// Answered, unless nil, is given each answer GeoJS gives, once it is
 	// kept.
 	Answered func(Answer)
-	// Now tells the time, normally time.Now.
+	// Now tells the time, normally time.Now in UTC.
 	Now func() time.Time
 	// ProcessLog receives GeoJS's failures.
 	ProcessLog *slog.Logger

internal/reputation/abuseipdb.go

@@ -14,6 +14,7 @@ import (
 	"sync"
 	"time"
 
+	"cloud.google.com/go/civil"
 	"github.com/hashicorp/golang-lru/v2/simplelru"
 	"sneak.berlin/go/smallwebwaf/internal/alerts"
 )
@@ -27,8 +28,6 @@ const (
 	AbuseIPDBSource = "abuseipdb"
 	// maxAnswerBytes is the most of an answer of AbuseIPDB that is read.
 	maxAnswerBytes = 64 << 10
-	// day is the length of the day the checks are counted in, in UTC.
-	day = 24 * time.Hour
 )
 
 var (
@@ -50,9 +49,9 @@ type Score struct {
 // AbuseIPDB: the day, in UTC, of the checks Spent counts, zero before the
 // first, and the scores still in use.
 type Checks struct {
-	Day    time.Time `json:"day,omitzero"`
-	Spent  int       `json:"spent"`
-	Scores []Score   `json:"scores"`
+	Day    civil.Date `json:"day,omitzero"`
+	Spent  int        `json:"spent"`
+	Scores []Score    `json:"scores"`
 }
 
 // AbuseIPDBParams are what NewAbuseIPDB needs.
@@ -93,7 +92,7 @@ type AbuseIPDB struct {
 	// checking are the clients whose check is under way.
 	checking map[netip.Prefix]bool
 	// day is the day, in UTC, of the checks spent counts.
-	day   time.Time
+	day   civil.Date
 	spent int
 	// checks and failures count the checks made and those that failed,
 	// and retryAt is when a client may be checked again after the last
@@ -143,7 +142,7 @@ func (a *AbuseIPDB) Hit(
 		return kept.Score, kept.Score >= a.params.MinScore
 	}
 
-	if today := now.Truncate(day); !a.day.Equal(today) {
+	if today := civil.DateOf(now.UTC()); a.day != today {
 		a.day, a.spent = today, 0
 	}
 
@@ -190,7 +189,7 @@ func (a *AbuseIPDB) BudgetLeft() int {
 	a.mu.Lock()
 	defer a.mu.Unlock()
 
-	if !a.day.Equal(a.params.Now().Truncate(day)) {
+	if a.day != civil.DateOf(a.params.Now().UTC()) {
 		return a.params.DailyBudget
 	}
 

internal/reputation/abuseipdb_test.go

@@ -202,6 +202,43 @@ func TestDailyBudgetKeptAcrossARestartAndWholeAgainAsTheDayEnds(t *testing.T) {
 	})
 }
 
+func TestChecksAreCountedInUTCDaysWhateverTheClocksZone(t *testing.T) {
+	t.Parallel()
+
+	synctest.Test(t, func(t *testing.T) {
+		// A clock 14 hours ahead of UTC, whose day starts at 10:00 UTC.
+		ahead := time.FixedZone("UTC+14", 14*60*60)
+		p := abuseIPDBParams()
+		p.DailyBudget = 1
+		p.Now = func() time.Time { return time.Now().In(ahead) }
+		abuseIPDB := &abuseIPDBStandIn{scores: map[string]int64{suspect: 100}}
+		checker := newAbuseIPDB(abuseIPDB, p)
+
+		// At 09:00 UTC the one check is spent.
+		time.Sleep(9 * time.Hour)
+		hitFrom(t, checker, suspect, true)
+		synctest.Wait()
+		wantBudgetLeft(t, checker, 0)
+
+		// At 11:00 UTC the clock's day has changed, but the UTC day has not.
+		time.Sleep(2 * time.Hour)
+		wantBudgetLeft(t, checker, 0)
+
+		encoded, err := json.Marshal(checker.Snapshot())
+		if err != nil {
+			t.Fatalf("encode: %v", err)
+		}
+
+		if !strings.Contains(string(encoded), `"day":"2000-01-01"`) {
+			t.Errorf("reputation.json would hold %s, want the day 2000-01-01", encoded)
+		}
+
+		// At 00:00 UTC the budget is whole again.
+		time.Sleep(13 * time.Hour)
+		wantBudgetLeft(t, checker, 1)
+	})
+}
+
 func TestFailedCheckGivesNoScoreAndNoClientIsCheckedForAMinute(t *testing.T) {
 	t.Parallel()
 

internal/rproxy/limits_test.go

@@ -920,53 +920,72 @@ func TestAVisitorThatStopsALittleShortHasTheConnectionClosedWhenTheAnswerIsCutOf
 
 	const limit = 300 * time.Millisecond
 
-	headersRead := make(chan struct{})
-	// letAppSendBody also runs when the test ends, as the app's server waits for
-	// the app.
-	letAppSendBody := sync.OnceFunc(func() { close(headersRead) })
-	standIn := startWAF(t, allow)
-	// The app sends its body once the visitor has the status and headers and the
-	// response time limit has run out since, so that rproxy cannot send it.
-	app := startApp(t, func(w http.ResponseWriter, r *http.Request) {
-		rc := http.NewResponseController(w)
-		_ = rc.EnableFullDuplex()
+	// With two parts, rproxy fails to send the first and then waits for the
+	// second, which the app sends only once rproxy has ended the request to it.
+	for _, tc := range []struct {
+		name  string
+		parts []string
+	}{
+		{"with the body in one part", []string{greeting}},
+		{"with the body in two parts", []string{greeting[:5], greeting[5:]}},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			t.Parallel()
 
-		w.Header().Set(contentLengthHeader, strconv.Itoa(len(greeting)))
+			headersRead := make(chan struct{})
+			// letAppSendBody also runs when the test ends, as the app's server waits
+			// for the app.
+			letAppSendBody := sync.OnceFunc(func() { close(headersRead) })
+			standIn := startWAF(t, allow)
+			// The app sends its body once the visitor has the status and headers and
+			// the response time limit has run out since, so that rproxy cannot send
+			// it. After each part, it reads the request's body, which ends when rproxy
+			// ends the request to it.
+			app := startApp(t, func(w http.ResponseWriter, r *http.Request) {
+				rc := http.NewResponseController(w)
+				_ = rc.EnableFullDuplex()
 
-		_ = rc.Flush()
+				w.Header().Set(contentLengthHeader, strconv.Itoa(len(greeting)))
 
-		<-headersRead
-		time.Sleep(limit)
+				_ = rc.Flush()
 
-		_, _ = io.WriteString(w, greeting)
-		_ = rc.Flush()
-		_, _ = io.Copy(io.Discard, r.Body)
-	})
+				<-headersRead
+				time.Sleep(limit)
 
-	t.Cleanup(letAppSendBody)
+				for _, part := range tc.parts {
+					_, _ = io.WriteString(w, part)
+					_ = rc.Flush()
+					_, _ = io.Copy(io.Discard, r.Body)
+				}
+			})
 
-	// The request time limit is far longer than dial's deadline.
-	addr, _ := startRProxy(t, standIn.URL, app.URL, map[string]string{
-		maxRequestTime:  "120000",
-		maxResponseTime: strconv.FormatInt(limit.Milliseconds(), 10),
-	})
+			t.Cleanup(letAppSendBody)
 
-	conn := dial(t, addr)
-	sendAllButALittle(t, conn)
+			// The request time limit is far longer than dial's deadline.
+			addr, _ := startRProxy(t, standIn.URL, app.URL, map[string]string{
+				maxRequestTime:  "120000",
+				maxResponseTime: strconv.FormatInt(limit.Milliseconds(), 10),
+			})
 
-	res, err := http.ReadResponse(bufio.NewReader(conn), nil)
-	if err != nil {
-		t.Fatalf("read the answer: %v", err)
-	}
+			conn := dial(t, addr)
+			sendAllButALittle(t, conn)
 
-	letAppSendBody()
+			res, err := http.ReadResponse(bufio.NewReader(conn), nil)
+			if err != nil {
+				t.Fatalf("read the answer: %v", err)
+			}
 
-	// If the connection stays open, dial's deadline ends this read with a timeout.
-	body, err := io.ReadAll(res.Body)
-	_ = res.Body.Close()
+			letAppSendBody()
 
-	if len(body) != 0 || !errors.Is(err, io.ErrUnexpectedEOF) {
-		t.Errorf("read %q (%v), want the connection closed", body, err)
+			// If the connection stays open, dial's deadline ends this read with a
+			// timeout.
+			body, err := io.ReadAll(res.Body)
+			_ = res.Body.Close()
+
+			if len(body) != 0 || !errors.Is(err, io.ErrUnexpectedEOF) {
+				t.Errorf("read %q (%v), want the connection closed", body, err)
+			}
+		})
 	}
 }
 

internal/rproxy/request.go

@@ -195,20 +195,6 @@ func (rq *request) forward(ctx context.Context) {
 	rq.startRequestTimer()
 	rq.upstreamStart = time.Now()
 	reverseProxy.ServeHTTP(rq.out, out)
-
-	// ReverseProxy ignores a failed flush, so it misses a short answer cut off when
-	// SWRP_MAX_RESPONSE_TIME_MS runs out; once a flush has failed, every later one
-	// fails too. Go's server would then keep the connection open while it reads
-	// the rest of a body that has not arrived whole. So that reading ends now, and
-	// the refusal keeps finish from extending it to SWRP_MAX_REQUEST_TIME_MS. The
-	// panic has Go's server close the connection, and log nothing; the deferred
-	// finish still runs.
-	if rq.out.status != http.StatusSwitchingProtocols &&
-		errors.Is(rq.rc.Flush(), os.ErrDeadlineExceeded) {
-		rq.refuse(http.StatusGatewayTimeout)
-		rq.stopPassingOnBody(time.Now())
-		panic(http.ErrAbortHandler)
-	}
 }
 
 // rewrite makes the request the app receives: the visitor's request, unchanged,
@@ -398,7 +384,18 @@ func (rq *request) refuse(status int) {
 func (rq *request) finish(ctx context.Context) {
 	rq.stopTimers()
 
-	if rq.refused.Load() == 0 {
+	// After a cut-off answer, the reading of a body that has not arrived whole
+	// ends now. Go's server would otherwise keep the connection open while it
+	// reads the rest. A flush fails if the time to send the answer ran out, and
+	// every flush after a failed one fails too. ReverseProxy ignores the failure,
+	// but panics if it was still waiting for more of the app's answer; finish runs
+	// either way. Before a status, a flush would send a 200; after a 101,
+	// ReverseProxy has taken over the connection.
+	switch {
+	case rq.out.status != 0 && rq.out.status != http.StatusSwitchingProtocols &&
+		errors.Is(rq.rc.Flush(), os.ErrDeadlineExceeded):
+		rq.stopPassingOnBody(time.Now())
+	case rq.refused.Load() == 0:
 		rq.stopPassingOnBody(rq.requestDeadline())
 	}
 

internal/rproxy/rproxy_test.go

@@ -1117,6 +1117,7 @@ func TestAnAnswerThatCannotBePassedOnIsAnswered502(t *testing.T) {
 					t.Error("the app was asked")
 				})
 				addr, out := startRProxy(t, backend(t), app.URL, map[string]string{
+					timeoutSetting:     "60000",
 					defaultDisposition: setting,
 				})
 
@@ -1140,7 +1141,9 @@ func TestAnAnswerThatCannotBePassedOnGetsNoReport(t *testing.T) {
 	t.Parallel()
 
 	standIn := startWAF(t, overOneMiB(dispositionDeny))
-	addr, out := startRProxy(t, standIn.URL, nowhere, nil)
+	addr, out := startRProxy(t, standIn.URL, nowhere, map[string]string{
+		timeoutSetting: "60000",
+	})
 
 	if got := get(t, addr, "/"); got.status != http.StatusBadGateway {
 		t.Errorf("answered %+v, want 502", got)

internal/state/state.go

@@ -171,9 +171,11 @@ type alertsFile struct {
 // check refuses the first entry without a field it needs, which would
 // otherwise be read as something the entry does not say. data is the
 // file, for a field that may be null or "" but not left out, which the
-// struct cannot tell apart.
+// struct cannot tell apart. Its toUTC then converts every time in it to
+// UTC, since an admin may write a time with an offset.
 type stateFile interface {
 	check(data []byte) error
+	toUTC()
 }
 
 // Load checks that files can be written in Dir, and reads the state files
@@ -918,6 +920,80 @@ func missing(i int, field string) error {
 	return fmt.Errorf("entry %d %w %q", i+1, errMissing, field)
 }
 
+// toUTC converts every time of each ban to UTC.
+func (f *bansFile) toUTC() {
+	for i := range f.Bans {
+		ban := &f.Bans[i]
+		convertToUTC(&ban.Start, ban.Expires, ban.Lifted, &ban.Notes.Request.Time)
+	}
+}
+
+// toUTC converts every time of each client to UTC.
+func (f *clientsFile) toUTC() {
+	for i := range f.Clients {
+		client := &f.Clients[i]
+		convertToUTC(&client.Minute.Start, &client.Hour.Start, &client.Day.Start,
+			&client.MinuteBytes.Start, &client.HourBytes.Start,
+			&client.DayBytes.Start, &client.MinuteRefusals.Start,
+			&client.History.FirstSeen, &client.History.LastSeen,
+			&client.History.LookedUp)
+	}
+}
+
+// toUTC converts both times of each answer to UTC.
+func (f *lookupsFile) toUTC() {
+	for i := range f.Lookups {
+		convertToUTC(&f.Lookups[i].Answered, &f.Lookups[i].Used)
+	}
+}
+
+// toUTC converts every time of each list, verdict and AbuseIPDB score to
+// UTC.
+func (f *reputationFile) toUTC() {
+	for i := range f.Lists {
+		convertToUTC(&f.Lists[i].Tried, &f.Lists[i].Fetched)
+	}
+
+	for i := range f.Verdicts {
+		convertToUTC(&f.Verdicts[i].Fetched)
+	}
+
+	for i := range f.AbuseIPDB.Scores {
+		convertToUTC(&f.AbuseIPDB.Scores[i].Fetched)
+	}
+}
+
+// toUTC converts every time of each cooldown, of the hour, of each alert
+// waiting and of each anomaly counter to UTC.
+func (f *alertsFile) toUTC() {
+	for i := range f.Cooldowns {
+		convertToUTC(&f.Cooldowns[i].Sent)
+	}
+
+	convertToUTC(&f.Hour.Start)
+
+	for _, waiting := range f.Waiting {
+		for i := range waiting {
+			convertToUTC(&waiting[i].Time)
+		}
+	}
+
+	for i := range f.AnomalyCounters {
+		counter := &f.AnomalyCounters[i]
+		convertToUTC(&counter.Minute.Start, &counter.Hour.Start,
+			&counter.MinuteBytes.Start, &counter.HourBytes.Start)
+	}
+}
+
+// convertToUTC converts each of times that is not nil to UTC.
+func convertToUTC(times ...*time.Time) {
+	for _, at := range times {
+		if at != nil {
+			*at = at.UTC()
+		}
+	}
+}
+
 // encodeOnePerLine encodes a state file whose entries, under key, are one
 // to a line, so that grep shows everything about one client.
 func encodeOnePerLine[E any](key string, entries []E) ([]byte, error) {
@@ -955,7 +1031,8 @@ func checkWritable(dir string) error {
 }
 
 // parse reads data, what the state file at path holds, into file, a
-// pointer to that file's struct, and checks its entries.
+// pointer to that file's struct, checks its entries, and converts every
+// time in it to UTC.
 func parse(path string, data []byte, file stateFile) error {
 	// The version is read first, so that a file of another version is
 	// refused for that, and not for an entry this version cannot read.
@@ -985,6 +1062,8 @@ func parse(path string, data []byte, file stateFile) error {
 		return fmt.Errorf("%s%s: %w", path, position(data, err), err)
 	}
 
+	file.toUTC()
+
 	return nil
 }
 

internal/state/state_test.go

@@ -14,6 +14,7 @@ import (
 	"os"
 	"path/filepath"
 	"reflect"
+	"regexp"
 	"slices"
 	"strconv"
 	"strings"
@@ -21,6 +22,7 @@ import (
 	"testing/synctest"
 	"time"
 
+	"cloud.google.com/go/civil"
 	"sneak.berlin/go/smallwebwaf/internal/alerts"
 	"sneak.berlin/go/smallwebwaf/internal/anomaly"
 	"sneak.berlin/go/smallwebwaf/internal/bans"
@@ -258,7 +260,7 @@ const filledReputationJSON = `{
         }
     ],
     "abuseipdb": {
-        "day": "2026-10-06T00:00:00Z",
+        "day": "2026-10-06",
         "spent": 3,
         "scores": [
             {
@@ -1306,7 +1308,7 @@ func TestEditOfEachFileTakenIn(t *testing.T) {
 		`"tried": "2026-10-06T00:00:00Z", "fetched": "2026-10-06T00:00:00Z", `+
 		`"lines": ["198.51.100.7"]}], "verdicts": [{"zone": "`+dnsblZone+`", `+
 		`"client": "198.51.100.7", "listed": true, "fetched": "2026-10-06T00:00:00Z"}], `+
-		`"abuseipdb": {"day": "2026-10-06T00:00:00Z", "spent": 9, "scores": [`+
+		`"abuseipdb": {"day": "2026-10-06", "spent": 9, "scores": [`+
 		`{"client": "198.51.100.7/32", "score": 80, "fetched": "2026-10-06T00:00:00Z"}]}}`)
 	wantTakenIn(t, lines, dir, reputationJSON)
 
@@ -1321,7 +1323,7 @@ func TestEditOfEachFileTakenIn(t *testing.T) {
 	}})
 
 	checks := reputation.Checks{
-		Day: midnight(), Spent: 9,
+		Day: civil.DateOf(midnight()), Spent: 9,
 		Scores: []reputation.Score{{Client: client, Score: 80, Fetched: midnight()}},
 	}
 	if got := params.AbuseIPDB.Snapshot(); !reflect.DeepEqual(got, checks) {
@@ -1350,6 +1352,62 @@ func TestEditOfEachFileTakenIn(t *testing.T) {
 	}
 }
 
+func TestTimesEditedWithAnOffsetWrittenBackInUTC(t *testing.T) {
+	t.Parallel()
+
+	dir := t.TempDir()
+	params := newParams(dir)
+	fill(params)
+	// A lifted ban, so that bans.json holds every time a ban has.
+	params.Ledger.Lift(netip.MustParseAddr("192.0.2.1"), midnight())
+
+	files := load(t, params)
+
+	err := files.WriteAll()
+	if err != nil {
+		t.Fatalf("write: %v", err)
+	}
+
+	// An admin saves each file with every time in it two hours ahead of
+	// UTC, midnight as "2026-10-06T02:00:00+02:00".
+	stamp := regexp.MustCompile(`"\d{4}-\d\d-\d\dT[^"]*Z"`)
+	ahead := time.FixedZone("UTC+2", 2*60*60)
+	written := map[string]string{}
+
+	for _, name := range []string{
+		bansJSON, clientsJSON, lookupsJSON, reputationJSON, alertsJSON,
+	} {
+		written[name] = readFile(t, filepath.Join(dir, name))
+		edited := stamp.ReplaceAllStringFunc(written[name], func(quoted string) string {
+			at, err := time.Parse(time.RFC3339Nano, strings.Trim(quoted, `"`))
+			if err != nil {
+				t.Fatalf("%s holds %s: %v", name, quoted, err)
+			}
+
+			return `"` + at.In(ahead).Format(time.RFC3339Nano) + `"`
+		})
+
+		if !strings.Contains(edited, "+02:00") {
+			t.Fatalf("%s holds no time:\n%s", name, edited)
+		}
+
+		edit(t, dir, name, edited)
+	}
+
+	// Each write takes its edit in first, and writes the same times back in
+	// UTC.
+	err = files.WriteAll()
+	if err != nil {
+		t.Fatalf("write: %v", err)
+	}
+
+	for name, want := range written {
+		if got := readFile(t, filepath.Join(dir, name)); got != want {
+			t.Errorf("%s written back as\n%s\nwant\n%s", name, got, want)
+		}
+	}
+}
+
 func TestOwnWritesAreNotTakenIn(t *testing.T) {
 	t.Parallel()
 
@@ -1837,10 +1895,12 @@ func fill(params state.Params) {
 		},
 		{Zone: dnsblZone, Client: client.Addr(), Listed: true, Fetched: now.Add(-time.Hour)},
 	})
-	params.AbuseIPDB.Load(reputation.Checks{Day: now, Spent: 3, Scores: []reputation.Score{
-		{Client: netip.MustParsePrefix("2001:db8::/64"), Fetched: now.Add(-2 * time.Hour)},
-		{Client: client, Score: 100, Fetched: now.Add(-time.Hour)},
-	}})
+	params.AbuseIPDB.Load(reputation.Checks{
+		Day: civil.DateOf(now), Spent: 3, Scores: []reputation.Score{
+			{Client: netip.MustParsePrefix("2001:db8::/64"), Fetched: now.Add(-2 * time.Hour)},
+			{Client: client, Score: 100, Fetched: now.Add(-time.Hour)},
+		},
+	})
 
 	// An alert waiting, a repeat of it the cooldown holds back, another
 	// alert waiting, and one past the two an hour, for the hour's summary.

internal/sww/sww_test.go

@@ -92,6 +92,31 @@ func (o *output) line(t *testing.T, key, value string) map[string]any {
 	return nil
 }
 
+// lineBeforeExit returns the first line whose msg is msg, waiting for it
+// while sww runs. It waits as long as that takes, so that a slow start
+// cannot fail the test, and fails the test if sww exits first.
+func (o *output) lineBeforeExit(
+	t *testing.T, msg string, exited <-chan int,
+) map[string]any {
+	t.Helper()
+
+	for {
+		fields := o.findLine(t, func(fields map[string]any) bool {
+			return fields["msg"] == msg
+		})
+		if fields != nil {
+			return fields
+		}
+
+		select {
+		case status := <-exited:
+			t.Fatalf("exit status %d while waiting for a line with msg %q; output:\n%s",
+				status, msg, o.text())
+		case <-time.After(pollInterval):
+		}
+	}
+}
+
 // findLine returns the first line written so far for which matches is true, or
 // nil.
 func (o *output) findLine(
@@ -236,11 +261,12 @@ func TestServesUntilToldToStop(t *testing.T) {
 	}()
 
 	// The default rule file is read.
-	if rules := out.line(t, "msg", "read the rule files")["rules"]; rules != 12.0 {
+	readRules := out.lineBeforeExit(t, "read the rule files", exited)
+	if rules := readRules["rules"]; rules != 12.0 {
 		t.Errorf("read %v rules from the default rule file, want 12", rules)
 	}
 
-	starting := out.line(t, "msg", "starting")
+	starting := out.lineBeforeExit(t, "starting", exited)
 	wantStartingLine(t, starting, dir)
 
 	addr, _ := starting["address"].(string)
@@ -286,7 +312,7 @@ func TestLogLevelHoldsBackTheLessSevereProcessLines(t *testing.T) {
 		}, out)
 	}()
 
-	out.line(t, "msg", "fetching a list failed")
+	out.lineBeforeExit(t, "fetching a list failed", exited)
 	stop()
 
 	select {
@@ -1261,7 +1287,7 @@ func runUntilStopped(
 		exited <- run(ctx, env, out)
 	}()
 
-	addr, _ := out.line(t, "msg", "starting")["address"].(string)
+	addr, _ := out.lineBeforeExit(t, "starting", exited)["address"].(string)
 	use("http://" + addr + "/")
 	stop()
 

internal/sww/waf_test.go

@@ -9,10 +9,14 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
+	"regexp"
 	"strings"
 	"syscall"
 	"testing"
 	"time"
+	// The time zone database, so that the process TestMainRunsWAF starts
+	// finds the zone TZ names on any host.
+	_ "time/tzdata"
 
 	"sneak.berlin/go/smallwebwaf/internal/sww"
 	"sneak.berlin/go/smallwebwaf/internal/waf"
@@ -37,6 +41,14 @@ func TestMain(m *testing.M) {
 func TestMainRunsWAF(t *testing.T) {
 	t.Parallel()
 
+	// Kiritimati is 14 hours ahead of UTC; every time sww gives stays in UTC.
+	const zone = "Pacific/Kiritimati"
+
+	_, err := time.LoadLocation(zone)
+	if err != nil {
+		t.Fatalf("load %s: %v", zone, err)
+	}
+
 	binary, err := os.Executable()
 	if err != nil {
 		t.Fatalf("find the test binary: %v", err)
@@ -45,14 +57,16 @@ func TestMainRunsWAF(t *testing.T) {
 	ctx, cancel := context.WithTimeout(t.Context(), 3*waitLimit)
 	defer cancel()
 
+	dir := t.TempDir()
 	out := &output{}
 	cmd := exec.CommandContext(ctx, binary) //nolint:gosec // this test binary
 	cmd.Stdout = out
 
 	cmd.Env = append(os.Environ(),
+		"TZ="+zone,
 		commandForMain+"="+wafCommand,
 		listenAddr+"="+localhost+":0",
-		stateDir+"="+t.TempDir(),
+		stateDir+"="+dir,
 		rulesDir+"="+t.TempDir(),
 		lookupSource+"=off")
 
@@ -66,9 +80,11 @@ func TestMainRunsWAF(t *testing.T) {
 		_ = cmd.Wait()
 	})
 
-	addr, _ := out.line(t, "msg", "starting")["address"].(string)
+	starting := out.line(t, "msg", "starting")
+	addr, _ := starting["address"].(string)
 	ask(t, addr, "/", http.StatusOK, waf.DispositionAllow)
 
+	// The files are written as sww stops.
 	err = cmd.Process.Signal(syscall.SIGTERM)
 	if err != nil {
 		t.Fatalf("signal: %v", err)
@@ -76,7 +92,39 @@ func TestMainRunsWAF(t *testing.T) {
 
 	err = cmd.Wait()
 	if err != nil {
-		t.Errorf("exit: %v; output:\n%s", err, out.text())
+		t.Fatalf("exit: %v; output:\n%s", err, out.text())
+	}
+
+	wantUTC(t, "the process line", starting["time"])
+	wantUTC(t, "the request line", out.line(t, "type", "request")["time"])
+
+	path := filepath.Join(dir, "clients.json")
+
+	clients, err := os.ReadFile(path) //nolint:gosec // a file in the test's directory
+	if err != nil {
+		t.Fatalf("read clients.json: %v", err)
+	}
+
+	stamp := regexp.MustCompile(`"\d{4}-\d\d-\d\dT[^"]*"`)
+
+	times := stamp.FindAllString(string(clients), -1)
+	if len(times) == 0 {
+		t.Errorf("clients.json holds no time:\n%s", clients)
+	}
+
+	for _, stored := range times {
+		wantUTC(t, "clients.json", strings.Trim(stored, `"`))
+	}
+}
+
+// wantUTC checks that value, a time read from the log line or file that
+// where names, is in UTC.
+func wantUTC(t *testing.T, where string, value any) {
+	t.Helper()
+
+	text, _ := value.(string)
+	if !strings.HasSuffix(text, "Z") {
+		t.Errorf("%s gives the time %v, want one in UTC", where, value)
 	}
 }