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.