diff --git a/GVFS/GVFS.Platform.Windows/EnumerationFailureTracker.cs b/GVFS/GVFS.Platform.Windows/EnumerationFailureTracker.cs new file mode 100644 index 000000000..d8ecbc201 --- /dev/null +++ b/GVFS/GVFS.Platform.Windows/EnumerationFailureTracker.cs @@ -0,0 +1,212 @@ +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Threading; + +namespace GVFS.Platform.Windows +{ + /// + /// Why a directory-enumeration Get failed to find its enumeration ID. Recorded on the failure + /// telemetry so self-inflicted causes can be told apart from ProjFS races outside gvfs.exe's + /// control. These values are a case-sensitive contract consumed by the release-readiness + /// telemetry dashboard; keep them in sync with its cause bucketing. + /// + public enum EnumerationFailureReason + { + NeverSeen = 0, // ProjFS delivered an ID GVFS never held: never started, or from before a provider restart (outside gvfs.exe's control). + Evicted, // GVFS's own stale-enumeration eviction removed a live enumeration (self-inflicted). + EndedRecently, // ProjFS delivered a Get racing or following the End for the same enumeration - a benign close/query race (outside gvfs.exe's control). + } + + /// + /// Tracks the state needed to classify and rate-limit "Failed to find active enumeration ID" + /// failures, keyed by ProjFS enumeration GUID: + /// + /// - Recently ended IDs, so a Get that races or follows the End for the same enumeration is + /// attributed to a benign close/query race () + /// rather than an ID GVFS never held. + /// - Recently reported IDs, so the error is emitted once per ID within a window instead of once + /// per retry when a caller re-enumerates a lost handle in a loop. + /// + /// Eviction (a separate concern owned by the virtualizer) is passed in to + /// as a flag rather than tracked here. + /// + /// Thread-safety: the enumeration callbacks run concurrently on many ProjFS worker threads, so + /// this deliberately uses lock-free state rather + /// than a coarse lock, which would serialize the hot enumeration path. GUIDs are never reused, so + /// entries are bounded purely by age. + /// + public class EnumerationFailureTracker + { + // ProjFS can deliver a Get that races the End for the same handle (a query in flight while the + // directory handle is closing, or the querying process dying mid-enumeration). Ended IDs are + // retained this long so such a Get is attributed to a recently-ended enumeration. + private static readonly TimeSpan DefaultRecentlyEndedRetention = TimeSpan.FromSeconds(30); + + // A Get miss for the same ID can repeat in a tight loop (a caller re-enumerating a handle + // whose Start GVFS lost, e.g. across a provider restart). The error is emitted once per ID + // within this window so the machine-based signal survives without the per-machine event storm. + private static readonly TimeSpan DefaultReportedMissingRetention = TimeSpan.FromMinutes(5); + + // GVFS's own stale-enumeration eviction removes a live enumeration that ProjFS never ended. + // Evicted IDs are retained this long so a later Get for one is attributed to eviction rather + // than a never-held ID. This is twice the default stale-enumeration timeout (5 minutes), the + // window the virtualizer's eviction sweep uses to decide an enumeration is stale. + private static readonly TimeSpan DefaultRecentlyEvictedRetention = TimeSpan.FromMinutes(10); + + // Throttle for the age-based prune. The prune runs from every record point (RecordEnded, + // RecordEvicted, TryReserveReport), so the maps stay bounded even if one callback (e.g. End) + // stops arriving. + private static readonly TimeSpan DefaultPruneInterval = TimeSpan.FromSeconds(30); + + // Key: the ProjFS enumeration GUID that was ended. Value: the Environment.TickCount64 + // (monotonic milliseconds) at which EndDirectoryEnumeration recorded it. + private readonly ConcurrentDictionary recentlyEnded = new ConcurrentDictionary(); + + // Key: the ProjFS enumeration GUID for which a miss error was already emitted. Value: the + // Environment.TickCount64 (monotonic milliseconds) of that first report. + private readonly ConcurrentDictionary recentlyReportedMissing = new ConcurrentDictionary(); + + // Key: the ProjFS enumeration GUID that GVFS's stale-enumeration eviction removed. Value: the + // Environment.TickCount64 (monotonic milliseconds) at which it was evicted. + private readonly ConcurrentDictionary recentlyEvicted = new ConcurrentDictionary(); + + private readonly TimeSpan recentlyEndedRetention; + private readonly TimeSpan reportedMissingRetention; + private readonly TimeSpan recentlyEvictedRetention; + private readonly TimeSpan pruneInterval; + + // Monotonic (Environment.TickCount64, milliseconds) timestamp of the last prune. + private long lastPruneTickCount = Environment.TickCount64; + + public EnumerationFailureTracker() + : this(DefaultRecentlyEndedRetention, DefaultReportedMissingRetention, DefaultRecentlyEvictedRetention, DefaultPruneInterval) + { + } + + public EnumerationFailureTracker( + TimeSpan recentlyEndedRetention, + TimeSpan reportedMissingRetention, + TimeSpan recentlyEvictedRetention, + TimeSpan pruneInterval) + { + this.recentlyEndedRetention = recentlyEndedRetention; + this.reportedMissingRetention = reportedMissingRetention; + this.recentlyEvictedRetention = recentlyEvictedRetention; + this.pruneInterval = pruneInterval; + } + + /// + /// Records that an enumeration has ended. The caller MUST call this before removing the ID from + /// its active-enumeration collection, so a Get that races the removal always finds the ID in + /// one collection or the other and is never mis-attributed to a never-held ID. + /// + public void RecordEnded(Guid enumerationId) + { + this.MaybePrune(); + this.recentlyEnded[enumerationId] = Environment.TickCount64; + } + + /// + /// Records that GVFS's stale-enumeration eviction removed . + /// The caller MUST call this before removing the ID from its active-enumeration collection so a + /// racing Get always finds the ID in one collection or the other; if the removal then loses the + /// race (e.g. a normal End removed it first), call to undo. + /// + public void RecordEvicted(Guid enumerationId) + { + this.MaybePrune(); + this.recentlyEvicted[enumerationId] = Environment.TickCount64; + } + + /// + /// Undoes a when the eviction lost the race to remove the ID from + /// the active collection, so a miss is not mis-attributed to eviction. + /// + public void UndoEvicted(Guid enumerationId) + { + this.recentlyEvicted.TryRemove(enumerationId, out _); + } + + /// + /// Classifies why a Get failed to find in the active + /// collection. Eviction is the most actionable (self-inflicted) cause and wins; otherwise a + /// recently-ended ID is a benign close/query race, and anything else was never held. + /// + public EnumerationFailureReason ClassifyMiss(Guid enumerationId) + { + if (this.recentlyEvicted.ContainsKey(enumerationId)) + { + return EnumerationFailureReason.Evicted; + } + + if (this.recentlyEnded.ContainsKey(enumerationId)) + { + return EnumerationFailureReason.EndedRecently; + } + + return EnumerationFailureReason.NeverSeen; + } + + /// + /// Reserves the single error report allowed for within the + /// reporting window. Returns true the first time the ID is seen missing and false for repeats, + /// so a caller's retry loop cannot produce a telemetry storm. + /// + public bool TryReserveReport(Guid enumerationId) + { + this.MaybePrune(); + return this.recentlyReportedMissing.TryAdd(enumerationId, Environment.TickCount64); + } + + // Prunes all three maps if the throttle interval has elapsed. Called from every record point so + // the maps stay bounded regardless of which callback is active. + private void MaybePrune() + { + if (this.recentlyEnded.IsEmpty && this.recentlyReportedMissing.IsEmpty && this.recentlyEvicted.IsEmpty) + { + return; + } + + long now = Environment.TickCount64; + long last = Interlocked.Read(ref this.lastPruneTickCount); + if (now - last < (long)this.pruneInterval.TotalMilliseconds) + { + return; + } + + if (Interlocked.CompareExchange(ref this.lastPruneTickCount, now, last) != last) + { + // Another thread just claimed this prune interval. + return; + } + + PruneByAge(this.recentlyEnded, now - (long)this.recentlyEndedRetention.TotalMilliseconds); + PruneByAge(this.recentlyReportedMissing, now - (long)this.reportedMissingRetention.TotalMilliseconds); + PruneByAge(this.recentlyEvicted, now - (long)this.recentlyEvictedRetention.TotalMilliseconds); + } + + private static void PruneByAge(ConcurrentDictionary map, long cutoffTickCount) + { + foreach (KeyValuePair tracked in map) + { + if (tracked.Value < cutoffTickCount) + { + map.TryRemove(tracked.Key, out _); + } + } + } + + /// + /// Test-only: runs the prune immediately, bypassing the throttle, so retention behavior can be + /// exercised deterministically. + /// + internal void PruneForTest() + { + Interlocked.Exchange( + ref this.lastPruneTickCount, + Environment.TickCount64 - (long)this.pruneInterval.TotalMilliseconds - 1); + this.MaybePrune(); + } + } +} diff --git a/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs b/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs index 7a6bad6f2..a89619fb4 100644 --- a/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs +++ b/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs @@ -59,23 +59,15 @@ public class WindowsFileSystemVirtualizer : FileSystemVirtualizer, IRequiredCall // the throttle cannot be disturbed by wall-clock adjustments. private long lastEnumerationEvictionSweepTickCount = Environment.TickCount64; - // Enumeration IDs recently removed by EvictStaleEnumerations, mapped to the monotonic tick at - // which they were evicted. Retained briefly so a later GetDirectoryEnumeration for an evicted - // ID can be attributed to GVFS eviction (self-inflicted) rather than a ProjFS unknown-ID - // delivery. Bounded by pruning during each sweep; empty while eviction is disabled (the default). - private readonly ConcurrentDictionary recentlyEvictedEnumerations = new ConcurrentDictionary(); + // Classifies and rate-limits "Failed to find active enumeration ID" failures (evicted vs + // recently-ended vs never-seen, and once-per-ID error de-duplication). The eviction sweep in + // this class records evictions into it via RecordEvicted. + private readonly EnumerationFailureTracker enumerationFailureTracker = new EnumerationFailureTracker(); - /// - /// Why a GetDirectoryEnumeration failed to find its enumeration ID. Recorded on the failure - /// telemetry so a self-inflicted eviction can be told apart from a ProjFS unknown-ID delivery. - /// Kept in sync with the telemetry bucketing in devprod.git.telemetry - /// (gvfs-regression-signatures.kql). - /// - public enum EnumerationFailureReason - { - Unknown = 0, // ProjFS delivered an ID GVFS never held or already ended (outside gvfs.exe's control). - Evicted, // GVFS's own stale-enumeration eviction removed a live enumeration (self-inflicted). - } + // Test-only seam: invoked inside EndDirectoryEnumerationCallback after the ended ID is + // recorded but before it is removed from activeEnumerations, so a test can interleave a + // GetDirectoryEnumeration and verify the record-before-remove ordering. Null in production. + private Action enumerationEndBeforeRemoveHookForTest; public WindowsFileSystemVirtualizer(GVFSContext context, GVFSGitObjects gitObjects) : this( @@ -207,24 +199,6 @@ private void EvictStaleEnumerations() { long now = Environment.TickCount64; - // Prune the eviction-tracking map on every sweep, independent of whether an eviction - // happens this pass, so entries never outlive the window in which a stale - // GetDirectoryEnumeration could still arrive for an evicted ID. (If this ran only when - // Count > max below, the last evicted batch would linger once activity subsided.) Guids - // are never reused, so there is no need to prune on re-add. Cheap no-op while empty - // (the default, since eviction is off). - if (!this.recentlyEvictedEnumerations.IsEmpty) - { - long trackingCutoff = now - (long)(2 * this.activeEnumerationStaleTimeout.TotalMilliseconds); - foreach (KeyValuePair tracked in this.recentlyEvictedEnumerations) - { - if (tracked.Value < trackingCutoff) - { - this.recentlyEvictedEnumerations.TryRemove(tracked.Key, out _); - } - } - } - if (this.activeEnumerations.Count <= this.maxActiveEnumerations) { return; @@ -237,9 +211,9 @@ private void EvictStaleEnumerations() if (entry.Value.LastActivityTickCount < cutoff) { // Record the eviction BEFORE removing from activeEnumerations so a concurrent - // GetDirectoryEnumeration for this ID always finds it in one map or the other, - // and is never mis-attributed to a ProjFS unknown-ID delivery. - this.recentlyEvictedEnumerations[entry.Key] = now; + // GetDirectoryEnumeration for this ID always finds it in one collection or the + // other, and is never mis-attributed to a ProjFS unknown-ID delivery. + this.enumerationFailureTracker.RecordEvicted(entry.Key); if (this.activeEnumerations.TryRemove(entry.Key, out _)) { evictedCount++; @@ -248,7 +222,7 @@ private void EvictStaleEnumerations() { // Lost the race (e.g. a normal EndDirectoryEnumeration removed it first); // it was not evicted by us, so undo the tracking entry. - this.recentlyEvictedEnumerations.TryRemove(entry.Key, out _); + this.enumerationFailureTracker.UndoEvicted(entry.Key); } } } @@ -278,6 +252,18 @@ internal int MaxActiveEnumerationsForTest set { this.maxActiveEnumerations = value; } } + internal Action EnumerationEndBeforeRemoveHookForTest + { + set { this.enumerationEndBeforeRemoveHookForTest = value; } + } + + internal bool ActiveEnumerationsContainsForTest(Guid enumerationId) + { + return this.activeEnumerations.ContainsKey(enumerationId); + } + + internal EnumerationFailureTracker EnumerationFailureTrackerForTest => this.enumerationFailureTracker; + /// /// Test-only: resets the sweep throttle and runs the same eviction path the enumeration hot /// callback runs, so eviction behavior can be exercised deterministically. @@ -511,20 +497,25 @@ public HResult GetDirectoryEnumerationCallback( ActiveEnumeration activeEnumeration = null; if (!this.activeEnumerations.TryGetValue(enumerationId, out activeEnumeration)) { - EventMetadata metadata = this.CreateEventMetadata(enumerationId); - metadata.Add("filterFileName", filterFileName); - metadata.Add("restartScan", restartScan); - - // Distinguish a failure caused by GVFS's own stale-enumeration eviction - // (self-inflicted, fixable) from ProjFS delivering an ID GVFS never held or - // already ended (outside gvfs.exe's control). Kept in sync with the telemetry - // bucketing in devprod.git.telemetry (gvfs-regression-signatures.kql). - EnumerationFailureReason enumerationFailureReason = this.recentlyEvictedEnumerations.ContainsKey(enumerationId) - ? EnumerationFailureReason.Evicted - : EnumerationFailureReason.Unknown; - metadata.Add(nameof(EnumerationFailureReason), enumerationFailureReason.ToString()); - - this.Context.Tracer.RelatedError(metadata, nameof(this.GetDirectoryEnumerationCallback) + ": Failed to find active enumeration ID"); + // Distinguish why the ID is absent so self-inflicted causes can be told apart from + // ProjFS races outside gvfs.exe's control. The tracker attributes eviction (the + // only cause GVFS can act on), a recent End (a benign close/query race), or a + // never-held ID. + EnumerationFailureReason enumerationFailureReason = this.enumerationFailureTracker.ClassifyMiss(enumerationId); + + // Emit the full error only the first time a given ID is seen missing; the tracker + // suppresses the duplicate telemetry a caller's retry loop would otherwise generate + // (a single stuck enumeration has produced a very large number of events per machine + // in the field). The machine-based regression signal is preserved because the first + // occurrence still logs at Error. + if (this.enumerationFailureTracker.TryReserveReport(enumerationId)) + { + EventMetadata metadata = this.CreateEventMetadata(enumerationId); + metadata.Add("filterFileName", filterFileName); + metadata.Add("restartScan", restartScan); + metadata.Add(nameof(EnumerationFailureReason), enumerationFailureReason.ToString()); + this.Context.Tracer.RelatedError(metadata, nameof(this.GetDirectoryEnumerationCallback) + ": Failed to find active enumeration ID"); + } return HResult.InternalError; } @@ -597,6 +588,15 @@ public HResult EndDirectoryEnumerationCallback(Guid enumerationId) { try { + // Record the end BEFORE removing from activeEnumerations so a GetDirectoryEnumeration + // that races this end - ProjFS can deliver an in-flight Get concurrently with the + // handle-close End for the same enumeration - is attributed to a recently-ended + // enumeration rather than an ID GVFS never held. RecordEnded also prunes the tracking + // maps on a throttle, so they stay bounded from this path. + this.enumerationFailureTracker.RecordEnded(enumerationId); + + this.enumerationEndBeforeRemoveHookForTest?.Invoke(); + ActiveEnumeration activeEnumeration; if (!this.activeEnumerations.TryRemove(enumerationId, out activeEnumeration)) { diff --git a/GVFS/GVFS.UnitTests/Windows/EnumerationFailureTrackerTests.cs b/GVFS/GVFS.UnitTests/Windows/EnumerationFailureTrackerTests.cs new file mode 100644 index 000000000..ff36b9fd0 --- /dev/null +++ b/GVFS/GVFS.UnitTests/Windows/EnumerationFailureTrackerTests.cs @@ -0,0 +1,162 @@ +using System; +using GVFS.Platform.Windows; +using GVFS.Tests.Should; +using NUnit.Framework; + +namespace GVFS.UnitTests.Windows +{ + [TestFixture] + public class EnumerationFailureTrackerTests + { + // Retention/interval used by the classification and dedup tests, where entries must survive + // for the duration of the test (the default 30s throttle keeps the auto-prune from firing). + private static EnumerationFailureTracker CreateTracker() + { + return new EnumerationFailureTracker(); + } + + // Retention set to already-expired so a forced prune reclaims every entry deterministically, + // without any Thread.Sleep. The interval is left at a normal value; PruneForTest bypasses it. + private static EnumerationFailureTracker CreateImmediatelyExpiringTracker() + { + return new EnumerationFailureTracker( + recentlyEndedRetention: TimeSpan.FromMilliseconds(-1), + reportedMissingRetention: TimeSpan.FromMilliseconds(-1), + recentlyEvictedRetention: TimeSpan.FromMilliseconds(-1), + pruneInterval: TimeSpan.FromSeconds(30)); + } + + [TestCase] + public void ClassifyMiss_UnknownIdIsNeverSeen() + { + EnumerationFailureTracker tracker = CreateTracker(); + + tracker.ClassifyMiss(Guid.NewGuid()).ShouldEqual(EnumerationFailureReason.NeverSeen); + } + + [TestCase] + public void ClassifyMiss_RecordedEndIsEndedRecently() + { + EnumerationFailureTracker tracker = CreateTracker(); + Guid id = Guid.NewGuid(); + + tracker.RecordEnded(id); + + tracker.ClassifyMiss(id).ShouldEqual(EnumerationFailureReason.EndedRecently); + } + + [TestCase] + public void ClassifyMiss_RecordedEvictionIsEvicted() + { + EnumerationFailureTracker tracker = CreateTracker(); + Guid id = Guid.NewGuid(); + + tracker.RecordEvicted(id); + + tracker.ClassifyMiss(id).ShouldEqual(EnumerationFailureReason.Evicted); + } + + [TestCase] + public void ClassifyMiss_EvictionWinsOverRecordedEnd() + { + EnumerationFailureTracker tracker = CreateTracker(); + Guid id = Guid.NewGuid(); + + // Same ID present as both evicted and ended (the real case: eviction removed it, then a + // late End recorded it). Eviction is the more actionable cause and must win. + tracker.RecordEvicted(id); + tracker.RecordEnded(id); + + tracker.ClassifyMiss(id).ShouldEqual(EnumerationFailureReason.Evicted); + } + + [TestCase] + public void UndoEvicted_UndoesEviction() + { + EnumerationFailureTracker tracker = CreateTracker(); + Guid id = Guid.NewGuid(); + + // Eviction recorded the ID before removing it from the active set, then lost the race, so + // it undoes the record. The ID must no longer be attributed to eviction. + tracker.RecordEvicted(id); + tracker.UndoEvicted(id); + + tracker.ClassifyMiss(id).ShouldEqual(EnumerationFailureReason.NeverSeen); + } + + [TestCase] + public void TryReserveReport_ReturnsTrueOnceThenFalseForSameId() + { + EnumerationFailureTracker tracker = CreateTracker(); + Guid id = Guid.NewGuid(); + + tracker.TryReserveReport(id).ShouldBeTrue(); + tracker.TryReserveReport(id).ShouldBeFalse(); + tracker.TryReserveReport(id).ShouldBeFalse(); + } + + [TestCase] + public void TryReserveReport_IndependentPerId() + { + EnumerationFailureTracker tracker = CreateTracker(); + + tracker.TryReserveReport(Guid.NewGuid()).ShouldBeTrue(); + tracker.TryReserveReport(Guid.NewGuid()).ShouldBeTrue(); + } + + [TestCase] + public void PruneRemovesAgedEntries() + { + EnumerationFailureTracker tracker = CreateImmediatelyExpiringTracker(); + Guid id = Guid.NewGuid(); + + // Populate the maps. The default-interval throttle keeps the auto-prune inside RecordEnded, + // RecordEvicted and TryReserveReport from firing yet, so the entries are present. + tracker.RecordEnded(id); + tracker.TryReserveReport(id).ShouldBeTrue(); + tracker.ClassifyMiss(id).ShouldEqual(EnumerationFailureReason.EndedRecently); + tracker.TryReserveReport(id).ShouldBeFalse(); + + // Force the prune past the throttle: both aged entries are reclaimed. + tracker.PruneForTest(); + + // The ended entry is gone (now NeverSeen) and the dedup entry is gone (can report again). + tracker.ClassifyMiss(id).ShouldEqual(EnumerationFailureReason.NeverSeen); + tracker.TryReserveReport(id).ShouldBeTrue(); + } + + [TestCase] + public void PruneRemovesAgedEviction() + { + EnumerationFailureTracker tracker = CreateImmediatelyExpiringTracker(); + Guid id = Guid.NewGuid(); + + tracker.RecordEvicted(id); + tracker.ClassifyMiss(id).ShouldEqual(EnumerationFailureReason.Evicted); + + tracker.PruneForTest(); + + tracker.ClassifyMiss(id).ShouldEqual(EnumerationFailureReason.NeverSeen); + } + + [TestCase] + public void PruneKeepsEntriesWithinRetention() + { + // Long retention: a forced prune must NOT remove fresh entries. + EnumerationFailureTracker tracker = new EnumerationFailureTracker( + recentlyEndedRetention: TimeSpan.FromMinutes(10), + reportedMissingRetention: TimeSpan.FromMinutes(10), + recentlyEvictedRetention: TimeSpan.FromMinutes(10), + pruneInterval: TimeSpan.FromSeconds(30)); + Guid id = Guid.NewGuid(); + + tracker.RecordEnded(id); + tracker.TryReserveReport(id).ShouldBeTrue(); + + tracker.PruneForTest(); + + tracker.ClassifyMiss(id).ShouldEqual(EnumerationFailureReason.EndedRecently); + tracker.TryReserveReport(id).ShouldBeFalse(); + } + } +} diff --git a/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs b/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs index bfd4a0e09..0fda97907 100644 --- a/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs +++ b/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs @@ -328,7 +328,7 @@ public void StaleEnumerationsAreEvictedWhenEnabledButLiveOnesAreKept() } [TestCase] - public void GetDirectoryEnumerationTagsEvictedVersusUnknownId() + public void GetDirectoryEnumerationTagsMissReasonAndDeduplicates() { using (WindowsFileSystemVirtualizerTester tester = new WindowsFileSystemVirtualizerTester(this.Repo, new[] { "test" })) { @@ -355,11 +355,99 @@ public void GetDirectoryEnumerationTagsEvictedVersusUnknownId() mockTracker.RelatedErrorEvents.Any( e => e.Contains("Failed to find active enumeration ID") && e.Contains("\"EnumerationFailureReason\":\"Evicted\"")).ShouldBeTrue(); - // A Get for an ID GVFS never held is attributed to a ProjFS unknown-ID delivery. + // A Get for an ID GVFS never held is attributed to a never-seen delivery. Guid neverSeenId = Guid.NewGuid(); tester.MockVirtualization.RequiredCallbacks.GetDirectoryEnumerationCallback(4, neverSeenId, string.Empty, false, null).ShouldEqual(HResult.InternalError); mockTracker.RelatedErrorEvents.Any( - e => e.Contains("Failed to find active enumeration ID") && e.Contains("\"EnumerationFailureReason\":\"Unknown\"")).ShouldBeTrue(); + e => e.Contains("Failed to find active enumeration ID") && e.Contains("\"EnumerationFailureReason\":\"NeverSeen\"")).ShouldBeTrue(); + + // A Get that races/follows the End for the same enumeration is attributed to a benign + // close/query race, not a never-seen delivery. + Guid endedId = Guid.NewGuid(); + tester.MockVirtualization.RequiredCallbacks.StartDirectoryEnumerationCallback(5, endedId, "test", TriggeringProcessId, TriggeringProcessImageFileName).ShouldEqual(HResult.Ok); + tester.MockVirtualization.RequiredCallbacks.EndDirectoryEnumerationCallback(endedId).ShouldEqual(HResult.Ok); + tester.MockVirtualization.RequiredCallbacks.GetDirectoryEnumerationCallback(6, endedId, string.Empty, false, null).ShouldEqual(HResult.InternalError); + mockTracker.RelatedErrorEvents.Any( + e => e.Contains("Failed to find active enumeration ID") && e.Contains("\"EnumerationFailureReason\":\"EndedRecently\"")).ShouldBeTrue(); + + // Repeated Gets for the same missing ID are de-duplicated: the error is emitted once, + // so a caller's retry loop cannot produce a telemetry storm. + int errorsForNeverSeenId = mockTracker.RelatedErrorEvents.Count(e => e.Contains("\"EnumerationFailureReason\":\"NeverSeen\"")); + tester.MockVirtualization.RequiredCallbacks.GetDirectoryEnumerationCallback(7, neverSeenId, string.Empty, false, null).ShouldEqual(HResult.InternalError); + tester.MockVirtualization.RequiredCallbacks.GetDirectoryEnumerationCallback(8, neverSeenId, string.Empty, false, null).ShouldEqual(HResult.InternalError); + mockTracker.RelatedErrorEvents.Count(e => e.Contains("\"EnumerationFailureReason\":\"NeverSeen\"")).ShouldEqual(errorsForNeverSeenId); + } + } + + [TestCase] + public void EndDirectoryEnumerationRecordsEndedBeforeRemovingFromActive() + { + using (WindowsFileSystemVirtualizerTester tester = new WindowsFileSystemVirtualizerTester(this.Repo, new[] { "test" })) + { + tester.GitIndexProjection.EnumerationInMemory = true; + MockTracer mockTracker = this.Repo.Context.Tracer as MockTracer; + + Guid endedId = Guid.NewGuid(); + tester.MockVirtualization.RequiredCallbacks.StartDirectoryEnumerationCallback(1, endedId, "test", TriggeringProcessId, TriggeringProcessImageFileName).ShouldEqual(HResult.Ok); + + // Capture the state at the exact interleaving point a concurrent Get would observe: + // after End records the ended ID but before it removes it from activeEnumerations. This + // is the ordering the fix guarantees; a remove-before-record regression would fail it. + bool activeAtHook = false; + bool recentlyEndedAtHook = false; + tester.WindowsVirtualizer.EnumerationEndBeforeRemoveHookForTest = () => + { + activeAtHook = tester.WindowsVirtualizer.ActiveEnumerationsContainsForTest(endedId); + recentlyEndedAtHook = tester.WindowsVirtualizer.EnumerationFailureTrackerForTest.ClassifyMiss(endedId) == EnumerationFailureReason.EndedRecently; + }; + + tester.MockVirtualization.RequiredCallbacks.EndDirectoryEnumerationCallback(endedId).ShouldEqual(HResult.Ok); + + // The end was recorded before the removal, and the entry was still live at that point, + // so there is no window where the ID is absent from BOTH maps - a racing Get can never + // be misclassified NeverSeen. + recentlyEndedAtHook.ShouldBeTrue(); + activeAtHook.ShouldBeTrue(); + + // After End completes the ID is out of the active set but still tracked as recently ended. + tester.WindowsVirtualizer.ActiveEnumerationsContainsForTest(endedId).ShouldBeFalse(); + tester.WindowsVirtualizer.EnumerationFailureTrackerForTest.ClassifyMiss(endedId).ShouldEqual(EnumerationFailureReason.EndedRecently); + mockTracker.RelatedErrorEvents.Any(e => e.Contains("Failed to find active enumeration ID")).ShouldBeFalse(); + } + } + + [TestCase] + public void GetDirectoryEnumerationPrefersEvictedWhenIdIsBothEvictedAndEnded() + { + using (WindowsFileSystemVirtualizerTester tester = new WindowsFileSystemVirtualizerTester(this.Repo, new[] { "test" })) + { + tester.GitIndexProjection.EnumerationInMemory = true; + tester.WindowsVirtualizer.MaxActiveEnumerationsForTest = 1; + tester.WindowsVirtualizer.ActiveEnumerationStaleTimeoutForTest = TimeSpan.FromMilliseconds(20); + + Guid staleId = Guid.NewGuid(); + tester.MockVirtualization.RequiredCallbacks.StartDirectoryEnumerationCallback(1, staleId, "test", TriggeringProcessId, TriggeringProcessImageFileName).ShouldEqual(HResult.Ok); + + Thread.Sleep(200); + + Guid freshId = Guid.NewGuid(); + tester.MockVirtualization.RequiredCallbacks.StartDirectoryEnumerationCallback(2, freshId, "test", TriggeringProcessId, TriggeringProcessImageFileName).ShouldEqual(HResult.Ok); + + // Evict staleId: it lands in the recently-evicted map and leaves the active set. + tester.WindowsVirtualizer.ForceEnumerationEvictionSweepForTest(); + + // A late End for the same ID also records it in the recently-ended map (the removal + // itself fails because eviction already removed it), so the ID is now in BOTH maps. + tester.MockVirtualization.RequiredCallbacks.EndDirectoryEnumerationCallback(staleId).ShouldEqual(HResult.InternalError); + + MockTracer mockTracker = this.Repo.Context.Tracer as MockTracer; + + // The classifier checks eviction first, so the more actionable self-inflicted cause wins. + tester.MockVirtualization.RequiredCallbacks.GetDirectoryEnumerationCallback(3, staleId, string.Empty, false, null).ShouldEqual(HResult.InternalError); + mockTracker.RelatedErrorEvents.Any( + e => e.Contains("Failed to find active enumeration ID") && e.Contains("\"EnumerationFailureReason\":\"Evicted\"")).ShouldBeTrue(); + mockTracker.RelatedErrorEvents.Any( + e => e.Contains("Failed to find active enumeration ID") && e.Contains("\"EnumerationFailureReason\":\"EndedRecently\"")).ShouldBeFalse(); } }