Tests: make the session tests independent of WSL wall-clock steps (#296)

internal/session/create_test.go

@@ -114,7 +114,7 @@ func TestCreateMissingCharacterThenLogin(t *testing.T) {
 	h.send(opcode.SMSGLoginVerifyWorld, packet.NewWriter().U32(0).F32(0).F32(0).F32(0).F32(0).Bytes())
 	select {
 	case <-h.s.Ready():
-	case <-time.After(2 * time.Second):
+	case <-time.After(expectWait):
 		t.Fatal("not ready after the create")
 	}
 }
@@ -144,7 +144,7 @@ func TestCreateFailureEndsSession(t *testing.T) {
 			if err == nil || !strings.Contains(err.Error(), c.want) {
 				t.Fatalf("code %d: err = %v", c.code, err)
 			}
-		case <-time.After(2 * time.Second):
+		case <-time.After(expectWait):
 			t.Fatalf("code %d: session did not end", c.code)
 		}
 		if n := len(h.srv.Skipped()); n != 0 {
@@ -169,7 +169,7 @@ func TestCreateEmptyReplyEndsSession(t *testing.T) {
 		if err == nil || !strings.Contains(err.Error(), "empty reply") {
 			t.Fatalf("err = %v", err)
 		}
-	case <-time.After(2 * time.Second):
+	case <-time.After(expectWait):
 		t.Fatal("session did not end")
 	}
 }

internal/session/party_test.go

@@ -23,7 +23,7 @@ func fullStats(g packet.GUID, hp, maxHP uint16) []byte {
 
 func waitFor(t *testing.T, cond func() bool) {
 	t.Helper()
-	deadline := time.Now().Add(2 * time.Second)
+	deadline := time.Now().Add(expectWait)
 	for !cond() {
 		if time.Now().After(deadline) {
 			t.Fatal("condition not reached")

internal/session/replay_test.go

@@ -2,6 +2,7 @@ package session
 
 import (
 	"context"
+	"os"
 	"path/filepath"
 	"reflect"
 	"testing"
@@ -24,13 +25,34 @@ func allEvents(l *events.Log) []events.Event {
 // liveScenario drives a session through combat with names (one of them never answered),
 // vendor and quest requests whose events are inferred from the agent's own packets, a
 // knockback with its landing, and a logout, all recorded to a capture.
+//
+// The capture stamps each record with the wall clock, which a WSL2 host steps back about two
+// seconds every half minute (clock.go). A step inside the scenario puts later records before
+// earlier ones and the replay then lands the knockback in the past (17 decoded events, 18 live).
+// The scenario therefore runs again when the wall clock moved against the monotonic one while
+// it ran; the step is the host's, not the replay's, and the next run is a fresh one.
 func liveScenario(t *testing.T, path string) []events.Event {
+	t.Helper()
+	const attempts = 5
+	for i := 1; ; i++ {
+		_ = os.Remove(path) // capture.Create refuses a file that exists
+		began := time.Now()
+		live := liveScenarioOnce(t, path)
+		skew := time.Since(began) - time.Now().Round(0).Sub(began.Round(0)) // monotonic elapsed minus wall elapsed
+		if i == attempts || skew > -50*time.Millisecond && skew < 50*time.Millisecond {
+			return live
+		}
+		t.Logf("the wall clock stepped back %v during the scenario; running it again (%d of %d)", skew, i, attempts)
+	}
+}
+
+func liveScenarioOnce(t *testing.T, path string) []events.Event {
 	t.Helper()
 	w, err := capture.Create(path, []byte("SECRETPW"))
 	if err != nil {
 		t.Fatal(err)
 	}
-	h := startTapped(t, Options{NamesWait: 100 * time.Millisecond}, testKey, testKey, nil, w)
+	h := startClocked(t, Options{NamesWait: 100 * time.Millisecond}, testKey, testKey, nil, w, false) // the real clock: the events take the live stamps
 	h.enterWorld()
 	ctx := context.Background()
 	stranger := packet.GUID(0x40)

internal/session/session_test.go

@@ -53,6 +53,30 @@ func startWrapped(t *testing.T, opts Options, clientKey, serverKey []byte, wrap
 // startTapped is startWrapped with a tap on the client's connection (nil: none), the way
 // --capture records one.
 func startTapped(t *testing.T, opts Options, clientKey, serverKey []byte, wrap func(net.Conn) net.Conn, tap worldconn.Tap) *harness {
+	t.Helper()
+	return startClocked(t, opts, clientKey, serverKey, wrap, tap, true)
+}
+
+// expectWait is how long a test waits for a packet the session is about to send. The session
+// runs in real time (a walk leg takes a second, a flight a second or two), so a short
+// deadline turns a slow or loaded machine into a failure that says nothing about the code.
+// The wait ends when the packet arrives; the deadline only bounds a test that would fail anyway.
+const expectWait = 15 * time.Second
+
+// steadyClock is a session clock that only the monotonic clock drives. The host's wall clock
+// can be stepped (a WSL2 host steps it back about two seconds every half minute), and the
+// session slews its movement time towards the wall clock (clock.go), so a step during a walk
+// or a flight slows its client time for seconds and stretches the walk or skews a step's
+// time gap against its distance. The anticheat bounds this tolerates are covered in
+// clock_test.go; the tests of the walk, the flights and the packets' timing want the
+// session's own pace, which is what a steady wall clock gives.
+func steadyClock(start time.Time) func() time.Time {
+	return func() time.Time { return start.Add(time.Since(start)) }
+}
+
+// startClocked is startTapped with the session's clock steady (see steadyClock) or the real
+// one.
+func startClocked(t *testing.T, opts Options, clientKey, serverKey []byte, wrap func(net.Conn) net.Conn, tap worldconn.Tap, steady bool) *harness {
 	t.Helper()
 	cli, srvConn := net.Pipe()
 	t.Cleanup(func() { cli.Close(); srvConn.Close() })
@@ -78,6 +102,9 @@ func startTapped(t *testing.T, opts Options, clientKey, serverKey []byte, wrap f
 	}
 	h := &harness{t: t, srv: <-ch, run: make(chan error, 1)}
 	h.s = New(conn, opts)
+	if steady {
+		h.s.clockFn = steadyClock(h.s.start)
+	}
 	go func() { h.run <- h.s.Run(context.Background()) }()
 	// Ruling P1/P2: no Run goroutine outlives its test. Closing the pipes ends Run;
 	// Done closes before Run returns into the buffered h.run, drained or not.
@@ -115,7 +142,7 @@ func charEnumBody(chars ...Character) []byte {
 
 func (h *harness) expect(op uint16) worldconn.Packet {
 	h.t.Helper()
-	p, err := h.srv.Expect(op, 2*time.Second)
+	p, err := h.srv.Expect(op, expectWait)
 	if err != nil {
 		h.t.Fatal(err)
 	}
@@ -140,7 +167,7 @@ func (h *harness) enterWorld() {
 	h.expect(opcode.CMSGSetActiveMover)
 	select {
 	case <-h.s.Ready():
-	case <-time.After(2 * time.Second):
+	case <-time.After(expectWait):
 		h.t.Fatal("not ready")
 	}
 }
@@ -443,7 +470,7 @@ func TestPongTimeoutDisconnects(t *testing.T) {
 		if !errors.Is(err, ErrDisconnected) {
 			t.Fatalf("err = %v", err)
 		}
-	case <-time.After(2 * time.Second):
+	case <-time.After(expectWait):
 		t.Fatal("no disconnect without pongs")
 	}
 }
@@ -554,7 +581,7 @@ func TestLockedCharacterLoginIsRetried(t *testing.T) {
 	h.expect(opcode.CMSGSetActiveMover)
 	select {
 	case <-h.s.Ready():
-	case <-time.After(2 * time.Second):
+	case <-time.After(expectWait):
 		t.Fatal("not ready after the retry")
 	}
 	if !strings.Contains(log.String(), "retrying") {
@@ -576,7 +603,7 @@ func TestLockedCharacterGivesUpAfterRetries(t *testing.T) {
 		if err == nil || !strings.Contains(err.Error(), "code 1") {
 			t.Fatalf("err = %v", err)
 		}
-	case <-time.After(2 * time.Second):
+	case <-time.After(expectWait):
 		t.Fatal("session did not give up")
 	}
 }