Late-report test: edit after the clock-skew allowance; stamp a report's sync time when the comparison began

e2e/multiroot_scenarios_test.go

@@ -480,6 +480,14 @@ func TestMultiRootScenario_ALateReportDoesNotHideADivergence(t *testing.T) {
 			if err := a.Daemon.Store.SetAgreedHashForRoot(gameID, b.NodeID(), "config", ""); err != nil {
 				t.Fatal(err)
 			}
+			// With no base, the edits are judged against when the two were
+			// last confirmed the same, and only one made more than the 2 s
+			// clock-skew allowance after it counts as new (DetectConflict). A
+			// refresh the setup's own reports started can stamp that time
+			// after SettleSync returns; edits made in the next two seconds
+			// then read as neither side having changed, and the test failed on
+			// its own timing (Windows CI: stamped 1.8 s before the edits).
+			waitPastLastSynced(t, a, b.NodeID())
 
 			writeIn(t, aConfig, "settings.ini", "A-version")
 			writeIn(t, bConfig, "settings.ini", "B-version")
@@ -514,6 +522,32 @@ func TestMultiRootScenario_ALateReportDoesNotHideADivergence(t *testing.T) {
 	}
 }
 
+// waitPastLastSynced waits until a's "last synced" time for the peer has
+// stopped moving and lies further back than the clock-skew allowance a
+// location without a merge base is judged with (syncengine's
+// clockSkewToleranceMs, 2 s), so an edit made after it counts as new.
+func waitPastLastSynced(t *testing.T, a *testutil.TestDaemon, peerID string) {
+	t.Helper()
+	const past = 3 * time.Second // the 2 s allowance, and a margin
+	stamp := func() string {
+		p, err := a.Daemon.Store.GetPeer(peerID)
+		if err != nil || !p.LastSynced.Valid {
+			return ""
+		}
+		return p.LastSynced.String
+	}
+	deadline := time.Now().Add(45 * time.Second)
+	for time.Now().Before(deadline) {
+		s := stamp()
+		at, err := time.Parse("2006-01-02T15:04:05.000Z", s)
+		if s == "" || (err == nil && time.Since(at) > past) {
+			return
+		}
+		time.Sleep(100 * time.Millisecond)
+	}
+	t.Fatalf("the last-synced time kept moving: %s", stamp())
+}
+
 // The location's own TestStaleBase_OneSidedEditDoesNotConflict. A report that
 // never arrives leaves the base behind both devices, with the push it was
 // about still on record — B holds exactly what A sent. An edit on A alone must

internal/p2p/syncengine/engine.go

@@ -393,7 +393,16 @@ func syncedNow() string { return time.Now().UTC().Format("2006-01-02T15:04:05.00
 // up to date with this save?" needs. The two are written together so they
 // cannot disagree about when.
 func (e *Engine) recordSynced(gameID, peerID string) {
-	ts := syncedNow()
+	e.recordSyncedAt(gameID, peerID, syncedNow())
+}
+
+// recordSyncedAt is recordSynced for a comparison that began at ts. The stamp
+// says the two devices were the same as of that time, and a location with no
+// merge base yet counts only the edits made after it as new. Stamped with the
+// time the comparison ended instead, it reached past edits made while it ran
+// — on a slow disk that is seconds — and an edit made on both devices then
+// read as neither having changed: one quietly replaced the other.
+func (e *Engine) recordSyncedAt(gameID, peerID, ts string) {
 	_ = e.Store.UpdatePeerLastSynced(peerID, ts)
 	_ = e.Store.UpdateGamePeerLastSynced(gameID, peerID, ts)
 }
@@ -1182,6 +1191,11 @@ func (e *Engine) ConfirmInSync(ctx context.Context, gameID string, peer Peer, cl
 // the lineage (making future local deletions of them propagate instead of
 // the file being pulled back).
 func (e *Engine) RefreshLineage(ctx context.Context, gameID string, peer Peer) {
+	// Taken before either side is read: whatever the comparison below finds,
+	// it found as of no earlier than this, and an edit made while it runs —
+	// after the peer's manifest was fetched, or after ours was read — must
+	// still count as made after the time it stamps (recordSyncedAt).
+	checkedAt := syncedNow()
 	game, err := e.Store.GetGame(gameID)
 	if err != nil {
 		return
@@ -1219,7 +1233,7 @@ func (e *Engine) RefreshLineage(ctx context.Context, gameID string, peer Peer) {
 	if local.ManifestHash() == remoteData.Manifest.ManifestHash() {
 		_ = e.Store.SetAgreedHash(gameID, peer.ID, local.ManifestHash())
 		if rootsAgree {
-			e.recordSynced(gameID, peer.ID)
+			e.recordSyncedAt(gameID, peer.ID, checkedAt)
 			e.notifySyncConfirmed(gameID)
 		}
 	}

internal/p2p/syncengine/engine_test.go

@@ -47,6 +47,9 @@ type fakeTransport struct {
 	// "sync-complete" once a pull's files are all written, before the sync
 	// that pulled them has finished.
 	onSyncEvent func(eventType string)
+	// onFetchManifest runs as the peer's manifest is served, before it is
+	// read: a test's way to stand in a comparison that is part-way through.
+	onFetchManifest func()
 }
 
 func (f *fakeTransport) FetchManifest(ctx context.Context, peer Peer, gameID string, q ManifestQuery) (ManifestResponse, error) {
@@ -63,6 +66,9 @@ func (f *fakeTransport) FetchManifest(ctx context.Context, peer Peer, gameID str
 	if f.manifestErr != nil {
 		return ManifestResponse{}, f.manifestErr
 	}
+	if f.onFetchManifest != nil {
+		f.onFetchManifest()
+	}
 	m, err := delta.BuildManifest(f.remoteDir)
 	if err != nil {
 		return ManifestResponse{}, err

internal/p2p/syncengine/stamp_test.go

@@ -0,0 +1,50 @@
+package syncengine
+
+import (
+	"context"
+	"testing"
+	"time"
+)
+
+// The time a peer's report confirms the two devices the same is the time the
+// comparison began, not the time it finished.
+//
+// A location with no merge base yet counts only the edits made after that
+// time as new. RefreshLineage stamped it once it had read both sides and
+// written the lineage — seconds later on a slow disk — so an edit made on both
+// devices while it ran read as neither having changed, and one replaced the
+// other with no conflict raised. CI: TestMultiRootScenario_ALateReportDoesNotHideADivergence
+// on Windows, "A=\"B-version\" B=\"B-version\"".
+func TestRefreshLineage_StampsWhenTheComparisonBegan(t *testing.T) {
+	env := setupEngine(t)
+	write(t, env.localDir, "save.dat", "same")
+	write(t, env.remoteDir, "save.dat", "same")
+
+	var fetchedAt time.Time
+	env.transport.onFetchManifest = func() {
+		fetchedAt = time.Now()
+		// The rest of the comparison taking a while, as it does on a busy
+		// machine: an edit made now is after the peer's side was read.
+		time.Sleep(100 * time.Millisecond)
+	}
+	env.engine.RefreshLineage(context.Background(), "game1", env.peer)
+
+	p, err := env.store.GetPeer(env.peer.ID)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if !p.LastSynced.Valid {
+		t.Fatal("identical sides were not stamped as synced")
+	}
+	stamped, err := time.Parse("2006-01-02T15:04:05.000Z", p.LastSynced.String)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if fetchedAt.IsZero() {
+		t.Fatal("the peer's manifest was never fetched")
+	}
+	if stamped.After(fetchedAt) {
+		t.Errorf("stamped synced at %s, %v after the peer's side was read: an edit made in between would not count as new",
+			stamped.Format(time.RFC3339Nano), stamped.Sub(fetchedAt))
+	}
+}