e2e: every failing test prints its daemons' logs

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() {

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 {

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")

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)
 	}

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

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 —

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")

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)

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

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.