diff --git a/e2e/multiroot_scenarios_test.go b/e2e/multiroot_scenarios_test.go index e6659650..16615064 100644 --- a/e2e/multiroot_scenarios_test.go +++ b/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 diff --git a/internal/p2p/syncengine/engine.go b/internal/p2p/syncengine/engine.go index f60d67fe..821b81f9 100644 --- a/internal/p2p/syncengine/engine.go +++ b/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) } } diff --git a/internal/p2p/syncengine/engine_test.go b/internal/p2p/syncengine/engine_test.go index 1ed654ff..aa501a7f 100644 --- a/internal/p2p/syncengine/engine_test.go +++ b/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 diff --git a/internal/p2p/syncengine/stamp_test.go b/internal/p2p/syncengine/stamp_test.go new file mode 100644 index 00000000..2300c4d4 --- /dev/null +++ b/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)) + } +}