From cf905b9654c28f3f18c9dd8e37168c1d75a42863 Mon Sep 17 00:00:00 2001 From: pjerra <71784785+pjerra@users.noreply.github.com> Date: Fri, 23 Oct 2026 02:04:14 +0200 Subject: [PATCH] session tests: keep the host's wall-clock steps and short deadlines from failing walk, flight and replay tests (#296) The WSL2 host steps its wall clock back about 2 s every 30 s. The session slews its movement time towards the wall clock, so a step during a walk or flight slows the client time for seconds (walk tests timed out at 2 s, FeatherFallMidFlight saw a step 0.03 yd over its bound), and the capture stamps records with the wall clock, so a step put records before earlier ones and the replay missed the knockback landing (17 decoded, 18 live). - harness: sessions run on a steady clock (monotonic-driven clockFn); packet, ready and condition waits are 15 s instead of 2 s (they end on arrival) - replay tests: the live scenario runs again when the wall clock stepped during it - no product code changed --- internal/session/create_test.go | 6 +++--- internal/session/party_test.go | 2 +- internal/session/replay_test.go | 24 ++++++++++++++++++++- internal/session/session_test.go | 37 +++++++++++++++++++++++++++----- 4 files changed, 59 insertions(+), 10 deletions(-) diff --git a/internal/session/create_test.go b/internal/session/create_test.go index 279b7e59..3fcb2aa1 100644 --- a/internal/session/create_test.go +++ b/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") } } diff --git a/internal/session/party_test.go b/internal/session/party_test.go index cf3ed8c0..1e959fef 100644 --- a/internal/session/party_test.go +++ b/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") diff --git a/internal/session/replay_test.go b/internal/session/replay_test.go index af7aef90..09e5ca4e 100644 --- a/internal/session/replay_test.go +++ b/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) diff --git a/internal/session/session_test.go b/internal/session/session_test.go index 41c187ff..eb135eae 100644 --- a/internal/session/session_test.go +++ b/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") } }