From 9878bc9f7cb3781c62e52e09b20776b15c99fb8b Mon Sep 17 00:00:00 2001 From: ChakraFusion <112588066+ChakraFusion@users.noreply.github.com> Date: Wed, 14 Oct 2026 11:49:09 +0200 Subject: [PATCH] e2e: every failing test prints its daemons' logs A timing failure in CI arrives as one line ("offers = []", "daemon never became ready") with nothing to say what the daemons did, and it rarely happens twice: the cloud-offer failure on Windows CI took 150 runs to see again. Only 12 tests printed the logs (logOnFailure), by asking for it. - testutil.NewTestDaemon prints the daemon's log when its test fails, after the daemon has stopped, so its shutdown is in it too. logOnFailure and its calls go, since every test now has it. - The CLI harness prints the daemon process's opensave.log before its home is removed, and a daemon that never became ready says whether its address was published and what the last `daemon status` answered. Co-Authored-By: Claude Opus 5.5 --- e2e/cli_harness_test.go | 31 +++++++++++++++++++++++++++++-- e2e/concurrent_sync_test.go | 3 --- e2e/deletion_window_test.go | 1 - e2e/failure_logs_test.go | 29 ----------------------------- e2e/journeys_test.go | 1 - e2e/keep_both_test.go | 2 -- e2e/last_synced_test.go | 1 - e2e/multiroot_scenarios_test.go | 1 - e2e/sync_soak_test.go | 2 -- e2e/watch_sync_gauntlet_test.go | 1 - testutil/harness.go | 20 ++++++++++++++++++++ 11 files changed, 49 insertions(+), 43 deletions(-) delete mode 100644 e2e/failure_logs_test.go diff --git a/e2e/cli_harness_test.go b/e2e/cli_harness_test.go index bf36de5f..a7c7fa47 100644 --- a/e2e/cli_harness_test.go +++ b/e2e/cli_harness_test.go @@ -97,11 +97,32 @@ func newCLI(t *testing.T) *cli { c := &cli{t: t, home: home, port: freePort(t)} t.Cleanup(func() { c.stopDaemon() + c.logIfFailed() _ = os.RemoveAll(home) }) return c } +// logIfFailed prints the log the daemon processes of a failed test wrote, +// before their home is removed with it. The daemon runs in a process of its +// own here, so its log is the file, not anything in this one: without it, a +// daemon that never became ready on CI said nothing about why. +func (c *cli) logIfFailed() { + if !c.t.Failed() { + return + } + raw, err := os.ReadFile(filepath.Join(c.home, ".opensave", "opensave.log")) + if err != nil { + c.t.Logf("---- no daemon log: %v ----", err) + return + } + const keep = 16 << 10 // the end is what explains a failure + if len(raw) > keep { + raw = raw[len(raw)-keep:] + } + c.t.Logf("---- daemon log ----\n%s", raw) +} + func freePort(t *testing.T) int { t.Helper() l, err := net.Listen("tcp", "127.0.0.1:0") @@ -183,17 +204,23 @@ func (c *cli) startDaemon() { c.daemon = cmd addrFile := filepath.Join(c.home, ".opensave", "daemon.addr") + // What the wait last saw, for the failure message: whether the address + // was ever published, and what the last status check answered. + seen := "the address was never published" deadline := time.Now().Add(30 * time.Second) for time.Now().Before(deadline) { if raw, err := os.ReadFile(addrFile); err == nil && strings.TrimSpace(string(raw)) != "" { // Published, but confirm it actually answers before returning. - if _, code := c.run("daemon", "status"); code == 0 { + out, code := c.run("daemon", "status") + if code == 0 { return } + seen = fmt.Sprintf("published as %s; `daemon status` last exited %d:\n%s", + strings.TrimSpace(string(raw)), code, out) } time.Sleep(150 * time.Millisecond) } - c.t.Fatalf("daemon never became ready on port %d:\n%s", c.port, log.String()) + c.t.Fatalf("daemon never became ready on port %d (%s)\noutput:\n%s", c.port, seen, log.String()) } func (c *cli) stopDaemon() { diff --git a/e2e/concurrent_sync_test.go b/e2e/concurrent_sync_test.go index 1c497b4f..09a3f929 100644 --- a/e2e/concurrent_sync_test.go +++ b/e2e/concurrent_sync_test.go @@ -137,7 +137,6 @@ func TestCrossingSyncs_AFirstPullIsNotTakenForADifferentSave(t *testing.T) { t.Run(fmt.Sprintf("gap=%v", gap), func(t *testing.T) { a := testutil.NewTestDaemon(t, "Crossing-A") b := testutil.NewTestDaemon(t, "Crossing-B") - logOnFailure(t, a, b) a.PairWith(b) files := manySaveFiles(121, "v1") for rel, c := range files { @@ -171,7 +170,6 @@ func TestCrossingSyncs_AnUpdateTakenPartWayIsNotAConflict(t *testing.T) { t.Run(fmt.Sprintf("gap=%v", gap), func(t *testing.T) { a := testutil.NewTestDaemon(t, "Update-A") b := testutil.NewTestDaemon(t, "Update-B") - logOnFailure(t, a, b) a.PairWith(b) v1 := manySaveFiles(121, "v1") for rel, c := range v1 { @@ -259,7 +257,6 @@ func TestCrossingSyncs_ADeviceStillWritingIsAskedAgain(t *testing.T) { func TestCrossingSyncs_APullOfAHalfWrittenSaveIsNotAConflict(t *testing.T) { a := testutil.NewTestDaemon(t, "Half-A") b := testutil.NewTestDaemon(t, "Half-B") - logOnFailure(t, a, b) a.PairWith(b) v1 := manySaveFiles(40, "v1") for rel, c := range v1 { diff --git a/e2e/deletion_window_test.go b/e2e/deletion_window_test.go index 879cb159..64aa3130 100644 --- a/e2e/deletion_window_test.go +++ b/e2e/deletion_window_test.go @@ -40,7 +40,6 @@ func TestDeletionImmediatelyAfterArrivalStillPropagates(t *testing.T) { func() { a := testutil.NewTestDaemon(t, "DelWin-A") b := testutil.NewTestDaemon(t, "DelWin-B") - logOnFailure(t, a, b) a.PairWith(b) a.WriteSave("keep.sav", "keep me") diff --git a/e2e/failure_logs_test.go b/e2e/failure_logs_test.go deleted file mode 100644 index b98deee3..00000000 --- a/e2e/failure_logs_test.go +++ /dev/null @@ -1,29 +0,0 @@ -package e2e - -import ( - "testing" - - "github.com/opensave/opensave/testutil" -) - -// logOnFailure prints each device's daemon log if the test fails. -// -// A timing failure in CI arrives as one line — "no conflict raised" — with -// nothing to say which sync ran, what it decided or what failed underneath, -// and it rarely happens twice in a row. The daemon already logs every step of -// a sync; this puts that record next to the failure instead of discarding it -// with the test. -func logOnFailure(t *testing.T, devices ...*testutil.TestDaemon) { - t.Helper() - t.Cleanup(func() { - if !t.Failed() { - return - } - for _, d := range devices { - t.Logf("---- log of %s ----", d.Name()) - for _, e := range d.Daemon.Log.History() { - t.Logf("%s %-7s %s", e.Timestamp, e.Level, e.Message) - } - } - }) -} diff --git a/e2e/journeys_test.go b/e2e/journeys_test.go index 0be45449..3719af8f 100644 --- a/e2e/journeys_test.go +++ b/e2e/journeys_test.go @@ -341,7 +341,6 @@ func TestJourney_RestoreOntoAFreshMachineAfterALoss(t *testing.T) { // here is what someone does on a new machine anyway, and it keeps the // restore aimed at this device. fresh := testutil.NewTestDaemon(t, "Loss-Fresh") - logOnFailure(t, original, fresh) if id := fresh.TrackGame("Loss"); id != gameID { t.Fatalf("step 2: both devices should derive the id %q, this one got %q", gameID, id) } diff --git a/e2e/keep_both_test.go b/e2e/keep_both_test.go index 897bedd8..b7b48558 100644 --- a/e2e/keep_both_test.go +++ b/e2e/keep_both_test.go @@ -82,7 +82,6 @@ func branchHolds(t *testing.T, st branchState, branch, rel string) string { func conflictOnBoth(t *testing.T, name string) (a, b *testutil.TestDaemon, gameID string) { t.Helper() a, b, gameID = pairAndTrack(t, name, map[string]string{"slot1.sav": "shared", "profile.sav": "p"}) - logOnFailure(t, a, b) time.Sleep(syncSettleWindow) a.WriteSave("slot1.sav", "A-version") b.WriteSave("slot1.sav", "B-version") @@ -194,7 +193,6 @@ func TestKeepBoth_OnBothDevicesEmptiesNeither(t *testing.T) { // device it was following. Following must fetch them instead. func TestBranchFollow_FetchesTheOtherDevicesSaveNotDeletesIt(t *testing.T) { a, b, gameID := pairAndTrack(t, "Follow", map[string]string{"slot1.sav": "main-save", "profile.sav": "main-profile"}) - logOnFailure(t, a, b) time.Sleep(syncSettleWindow) // A starts a fresh run on a new branch. Its own syncs are kept quiet, so diff --git a/e2e/last_synced_test.go b/e2e/last_synced_test.go index 3b160236..21b29f19 100644 --- a/e2e/last_synced_test.go +++ b/e2e/last_synced_test.go @@ -27,7 +27,6 @@ import ( func TestLastSynced_PerGamePerPeer(t *testing.T) { a := testutil.NewTestDaemon(t, "Stamp-A") b := testutil.NewTestDaemon(t, "Stamp-B") - logOnFailure(t, a, b) a.PairWith(b) // B does not adopt games it has not been told where to keep. That makes // a game tracked only on A one that A "syncs" with B and nothing moves — diff --git a/e2e/multiroot_scenarios_test.go b/e2e/multiroot_scenarios_test.go index e6659650..397749f8 100644 --- a/e2e/multiroot_scenarios_test.go +++ b/e2e/multiroot_scenarios_test.go @@ -23,7 +23,6 @@ func twoLocationPair(t *testing.T, name string, configFiles map[string]string) ( a, b *testutil.TestDaemon, gameID, aConfig, bConfig string) { t.Helper() a, b, gameID = pairAndTrack(t, name, map[string]string{"save.sav": "primary v1"}) - logOnFailure(t, a, b) aConfig = extraDir(t, a, "config") bConfig = extraDir(t, b, "config") diff --git a/e2e/sync_soak_test.go b/e2e/sync_soak_test.go index 08a679f6..1d92ab0b 100644 --- a/e2e/sync_soak_test.go +++ b/e2e/sync_soak_test.go @@ -26,7 +26,6 @@ func TestSoak_ManyAlternatingRoundsNeverConflict(t *testing.T) { } a, b, gameID := trackBothOverRelay(t, "Soak", map[string]string{"slot1.sav": "round-0"}) - logOnFailure(t, a, b) const rounds = 8 for round := 1; round <= rounds; round++ { @@ -91,7 +90,6 @@ func TestSoak_AddingAndDeletingFilesNeverConflicts(t *testing.T) { } a, b, gameID := trackBothOverRelay(t, "SoakFiles", map[string]string{"keep.sav": "constant"}) - logOnFailure(t, a, b) for round := 1; round <= 4; round++ { name := fmt.Sprintf("slot%d.sav", round) diff --git a/e2e/watch_sync_gauntlet_test.go b/e2e/watch_sync_gauntlet_test.go index 7c38385d..6708a892 100644 --- a/e2e/watch_sync_gauntlet_test.go +++ b/e2e/watch_sync_gauntlet_test.go @@ -57,7 +57,6 @@ func TestWatchAutoSyncChain(t *testing.T) { a := testutil.NewTestDaemon(t, "Chain-A") b := testutil.NewTestDaemon(t, "Chain-B") a.PairWith(b) - logOnFailure(t, a, b) a.WriteSave("seed.sav", "seed") restoreSyncOnTrack := suppressSyncOnTrack(a, b) // see sync_on_track_test.go diff --git a/testutil/harness.go b/testutil/harness.go index 9323e7b4..8d27aa6f 100644 --- a/testutil/harness.go +++ b/testutil/harness.go @@ -178,10 +178,30 @@ func NewTestDaemon(t *testing.T, name string) *TestDaemon { t.Cleanup(func() { srv.Stop() d.Stop() + td.logIfFailed(name) }) return td } +// logIfFailed prints this daemon's log when its test has failed. +// +// A timing failure in CI arrives as one line — "offers = []", "no conflict +// raised" — with nothing to say what the daemons did, and it rarely happens +// twice in a row: one seen on Windows CI took 150 runs to see again. The +// daemon already logs every step; this puts that record next to every +// failure, rather than only beside the tests that asked for it. Called once +// the daemon has stopped, so its shutdown is in it too; the name is passed in +// because Name reads it from a database that is closed by then. +func (td *TestDaemon) logIfFailed(name string) { + if !td.T.Failed() { + return + } + td.T.Logf("---- log of %s ----", name) + for _, e := range td.Daemon.Log.History() { + td.T.Logf("%s %-7s %s", e.Timestamp, e.Level, e.Message) + } +} + // API performs a JSON request against this daemon's API and decodes the // response into out (out may be nil). Non-2xx responses fail the test // unless allowError is set.