diff --git a/GVFS/GVFS.Common/GitStatusCache.cs b/GVFS/GVFS.Common/GitStatusCache.cs index 870dce1c7c..369adda87c 100644 --- a/GVFS/GVFS.Common/GitStatusCache.cs +++ b/GVFS/GVFS.Common/GitStatusCache.cs @@ -50,7 +50,11 @@ public class GitStatusCache : IDisposable private CancellationTokenSource shutdownTokenSource; private Task activeHydrationTask; - private volatile EnlistmentHydrationSummary cachedHydrationSummary; + private volatile HydrationCacheSnapshot hydrationCache = new HydrationCacheSnapshot(null, NamedPipeMessages.HydrationStatus.CacheState.NotComputed, 0); + private int hydrationInvalidationVersion; + private long hydrationRequestCount; + private long hydrationUnavailableCount; + private readonly Lock hydrationStatisticsLock = new Lock(); private Func projectedFolderCountProvider; @@ -119,6 +123,7 @@ public virtual void Shutdown() /// public virtual void Invalidate() { + Interlocked.Increment(ref this.hydrationInvalidationVersion); this.lastInvalidationTime = DateTime.UtcNow; this.cacheState = CacheState.Dirty; } @@ -142,9 +147,29 @@ public void RefreshAndWait() /// Returns the cached hydration summary if one has been computed, /// or null if no valid summary is available yet. /// - public EnlistmentHydrationSummary GetCachedHydrationSummary() + public EnlistmentHydrationSummary GetCachedHydrationSummary(out NamedPipeMessages.HydrationStatus.CacheInfo info) { - return this.cachedHydrationSummary; + HydrationCacheSnapshot snapshot = this.hydrationCache; + EnlistmentHydrationSummary summary = snapshot.Summary; + bool available = summary != null && summary.IsValid; + lock (this.hydrationStatisticsLock) + { + this.hydrationRequestCount++; + if (!available) + { + this.hydrationUnavailableCount++; + } + } + + info = new NamedPipeMessages.HydrationStatus.CacheInfo + { + State = snapshot.State, + CalculationId = summary?.Diagnostics?.CalculationId, + AgeMs = summary == null ? -1 : Math.Max(0, (long)(DateTime.UtcNow - snapshot.CompletedUtc).TotalMilliseconds), + Invalidated = snapshot.InvalidationVersion != Volatile.Read(ref this.hydrationInvalidationVersion), + CountsComplete = summary?.Diagnostics?.CountsComplete ?? false, + }; + return available ? summary : null; } /// @@ -253,6 +278,22 @@ public virtual bool WriteTelemetryandReset(EventMetadata metadata) } StatusStatistics statusStatistics = Interlocked.Exchange(ref this.statistics, new StatusStatistics()); + long hydrationRequests; + long hydrationUnavailable; + lock (this.hydrationStatisticsLock) + { + hydrationRequests = this.hydrationRequestCount; + hydrationUnavailable = this.hydrationUnavailableCount; + this.hydrationRequestCount = 0; + this.hydrationUnavailableCount = 0; + } + if (hydrationRequests > 0) + { + metadata["HydrationStatus.RequestCount"] = hydrationRequests; + metadata["HydrationStatus.UnavailableCount"] = hydrationUnavailable; + metadata["HydrationStatus.CurrentCacheState"] = this.hydrationCache.State; + wroteTelemetry = true; + } if (statusStatistics.BackgroundStatusScanCount > 0) { @@ -413,26 +454,24 @@ private void RebuildStatusCacheIfNeeded(bool ignoreBackoff) } } - private void UpdateHydrationSummary() + internal void UpdateHydrationSummary() { if (this.projectedFolderCountProvider == null) { + this.RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState.ProviderUnavailable); return; } - bool enabled = TEST_EnableHydrationSummaryOverride - ?? this.context.Repository.LibGit2RepoInvoker.GetConfigBoolOrDefault(GVFSConstants.GitConfig.ShowHydrationStatus, GVFSConstants.GitConfig.ShowHydrationStatusDefault); - if (!enabled) + if (!this.GetHydrationSummaryEnabled()) { + this.RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState.FeatureDisabled); return; } - HydrationStatusCircuitBreaker circuitBreaker = new HydrationStatusCircuitBreaker( - this.context.Enlistment.DotGVFSRoot, - this.context.Tracer); - + HydrationStatusCircuitBreaker circuitBreaker = this.CreateHydrationCircuitBreaker(); if (circuitBreaker.IsDisabled()) { + this.RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState.CircuitBreakerDisabled); return; } @@ -443,14 +482,25 @@ private void UpdateHydrationSummary() * Accessing it here ensures that the value is cached for when a user invokes "git status", * and this is also a convenient place to log telemetry for it. */ + int invalidationVersion = Volatile.Read(ref this.hydrationInvalidationVersion); + HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics + { + Caller = HydrationSummaryCaller.BackgroundCache, + FolderCountSource = HydrationFolderCountSource.Projection, + }; EnlistmentHydrationSummary hydrationSummary = - EnlistmentHydrationSummary.CreateSummary(this.context.Enlistment, this.context.FileSystem, this.context.Tracer, this.projectedFolderCountProvider, this.shutdownTokenSource.Token); + this.CreateHydrationSummary(diagnostics); + NamedPipeMessages.HydrationStatus.CacheState state = hydrationSummary.IsValid + ? diagnostics.CountsComplete ? NamedPipeMessages.HydrationStatus.CacheState.Available : NamedPipeMessages.HydrationStatus.CacheState.IncompleteData + : diagnostics.Outcome == HydrationSummaryOutcome.Cancelled ? NamedPipeMessages.HydrationStatus.CacheState.Cancelled + : diagnostics.Outcome == HydrationSummaryOutcome.Failed ? NamedPipeMessages.HydrationStatus.CacheState.Failed + : NamedPipeMessages.HydrationStatus.CacheState.InvalidCounts; + this.hydrationCache = new HydrationCacheSnapshot(hydrationSummary, state, invalidationVersion); EventMetadata metadata = new EventMetadata(); metadata.Add("Area", EtwArea); if (hydrationSummary.IsValid) { - this.cachedHydrationSummary = hydrationSummary; - + metadata["CalculationId"] = diagnostics.CalculationId.ToString("N"); metadata[nameof(hydrationSummary.TotalFolderCount)] = hydrationSummary.TotalFolderCount; metadata[nameof(hydrationSummary.TotalFileCount)] = hydrationSummary.TotalFileCount; metadata[nameof(hydrationSummary.HydratedFolderCount)] = hydrationSummary.HydratedFolderCount; @@ -464,36 +514,74 @@ private void UpdateHydrationSummary() } else if (hydrationSummary.Error != null) { - this.cachedHydrationSummary = null; circuitBreaker.RecordFailure(); metadata["Exception"] = hydrationSummary.Error.ToString(); this.context.Tracer.RelatedWarning( metadata, $"{nameof(GitStatusCache)}{nameof(RebuildStatusCacheIfNeeded)}: hydration summary could not be calculated.", - Keywords.Telemetry); + Keywords.None); } else { - // Invalid summary with no error — likely cancelled during shutdown - this.cachedHydrationSummary = null; this.context.Tracer.RelatedInfo( - $"{nameof(GitStatusCache)}{nameof(RebuildStatusCacheIfNeeded)}: hydration summary was cancelled."); + $"{nameof(GitStatusCache)}{nameof(RebuildStatusCacheIfNeeded)}: hydration summary outcome: {diagnostics.Outcome}."); } } catch (Exception ex) { - this.cachedHydrationSummary = null; + this.hydrationCache = new HydrationCacheSnapshot(null, NamedPipeMessages.HydrationStatus.CacheState.Failed, Volatile.Read(ref this.hydrationInvalidationVersion)); circuitBreaker.RecordFailure(); EventMetadata metadata = new EventMetadata(); metadata.Add("Area", EtwArea); - metadata.Add("Exception", ex.ToString()); - this.context.Tracer.RelatedError( + metadata.Add("ExceptionType", ex.GetType().FullName); + metadata.Add("ExceptionHResult", ex.HResult); + this.context.Tracer.RelatedWarning(new EventMetadata { ["Exception"] = ex.ToString() }, "Hydration cache update failed.", Keywords.None); + this.context.Tracer.RelatedWarning( metadata, $"{nameof(GitStatusCache)}{nameof(RebuildStatusCacheIfNeeded)}: Exception trying to update hydration summary cache.", Keywords.Telemetry); } } + internal virtual bool GetHydrationSummaryEnabled() + { + return TEST_EnableHydrationSummaryOverride + ?? this.context.Repository.LibGit2RepoInvoker.GetConfigBoolOrDefault(GVFSConstants.GitConfig.ShowHydrationStatus, GVFSConstants.GitConfig.ShowHydrationStatusDefault); + } + + internal virtual HydrationStatusCircuitBreaker CreateHydrationCircuitBreaker() + { + return new HydrationStatusCircuitBreaker(this.context.Enlistment.DotGVFSRoot, this.context.Tracer); + } + + internal virtual EnlistmentHydrationSummary CreateHydrationSummary(HydrationSummaryDiagnostics diagnostics) + { + return EnlistmentHydrationSummary.CreateSummary(this.context.Enlistment, this.context.FileSystem, this.context.Tracer, + this.projectedFolderCountProvider, this.shutdownTokenSource.Token, diagnostics); + } + + private void RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState state) + { + HydrationCacheSnapshot previous = this.hydrationCache; + this.hydrationCache = new HydrationCacheSnapshot(previous.Summary, state, previous.InvalidationVersion, previous.CompletedUtc); + } + + private sealed class HydrationCacheSnapshot + { + public HydrationCacheSnapshot(EnlistmentHydrationSummary summary, NamedPipeMessages.HydrationStatus.CacheState state, int invalidationVersion, DateTime? completedUtc = null) + { + this.Summary = summary; + this.State = state; + this.InvalidationVersion = invalidationVersion; + this.CompletedUtc = completedUtc ?? DateTime.UtcNow; + } + + public EnlistmentHydrationSummary Summary { get; } + public NamedPipeMessages.HydrationStatus.CacheState State { get; } + public int InvalidationVersion { get; } + public DateTime CompletedUtc { get; } + } + /// /// Rebuild the status cache. This will run the background status to /// generate status results, and update the serialized status cache diff --git a/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs b/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs index 5dbe7c335b..9c605af1d4 100644 --- a/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs +++ b/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs @@ -16,6 +16,7 @@ public class EnlistmentHydrationSummary public int TotalFileCount { get; private set; } public int TotalFolderCount { get; private set; } public Exception Error { get; private set; } = null; + public HydrationSummaryDiagnostics Diagnostics { get; private set; } public int HydratedFileCount => PlaceholderFileCount + ModifiedFileCount; public int HydratedFolderCount => PlaceholderFolderCount + ModifiedFolderCount; @@ -51,163 +52,176 @@ public static EnlistmentHydrationSummary CreateSummary( PhysicalFileSystem fileSystem, ITracer tracer, Func projectedFolderCountProvider, - CancellationToken cancellationToken = default) + CancellationToken cancellationToken = default, + HydrationSummaryDiagnostics diagnostics = null) { - Stopwatch totalStopwatch = Stopwatch.StartNew(); - Stopwatch phaseStopwatch = new Stopwatch(); + return CreateSummary(enlistment, fileSystem, tracer, projectedFolderCountProvider, new EnlistmentPathData(), cancellationToken, diagnostics); + } + internal static EnlistmentHydrationSummary CreateSummary( + GVFSEnlistment enlistment, + PhysicalFileSystem fileSystem, + ITracer tracer, + Func projectedFolderCountProvider, + EnlistmentPathData pathData, + CancellationToken cancellationToken = default, + HydrationSummaryDiagnostics diagnostics = null) + { + diagnostics = diagnostics ?? new HydrationSummaryDiagnostics(); + EnlistmentHydrationSummary summary = new EnlistmentHydrationSummary { Diagnostics = diagnostics }; + Stopwatch totalStopwatch = Stopwatch.StartNew(); try { - /* Getting all the file paths from git index is slow and we only need the total count, - * so we read the index file header instead of calling GetPathsFromGitIndex */ - phaseStopwatch.Restart(); - int totalFileCount = GetIndexFileCount(enlistment, fileSystem); - long indexReadMs = phaseStopwatch.ElapsedMilliseconds; + diagnostics.StartPhase(HydrationSummaryPhase.IndexRead); + summary.TotalFileCount = GetIndexFileCount(enlistment, fileSystem, diagnostics); + diagnostics.TotalFileCount = summary.TotalFileCount >= 0 ? summary.TotalFileCount : null; + diagnostics.FinishPhase(summary.TotalFileCount >= 0 ? HydrationDataState.Complete : HydrationDataState.Failed); cancellationToken.ThrowIfCancellationRequested(); - EnlistmentPathData pathData = new EnlistmentPathData(); - - /* FUTURE: These could be optimized to only deal with counts instead of full path lists */ - phaseStopwatch.Restart(); - pathData.LoadPlaceholdersFromDatabase(enlistment); - long placeholderLoadMs = phaseStopwatch.ElapsedMilliseconds; + diagnostics.StartPhase(HydrationSummaryPhase.Placeholders); + pathData.LoadPlaceholdersFromDatabase(enlistment, diagnostics); + summary.PlaceholderFileCount = pathData.PlaceholderFilePaths.Count; + summary.PlaceholderFolderCount = pathData.PlaceholderFolderPaths.Count; + diagnostics.PlaceholderFileCount = summary.PlaceholderFileCount; + diagnostics.PlaceholderFolderCount = summary.PlaceholderFolderCount; + diagnostics.FinishPhase(HydrationDataState.Complete); cancellationToken.ThrowIfCancellationRequested(); - phaseStopwatch.Restart(); - pathData.LoadModifiedPaths(enlistment, tracer); - long modifiedPathsLoadMs = phaseStopwatch.ElapsedMilliseconds; + diagnostics.StartPhase(HydrationSummaryPhase.ModifiedPaths); + pathData.LoadModifiedPaths(enlistment, tracer, diagnostics); + summary.ModifiedFileCount = pathData.ModifiedFilePaths.Count; + summary.ModifiedFolderCount = pathData.ModifiedFolderPaths.Count; + diagnostics.ModifiedFileCount = diagnostics.ModifiedPathsState == HydrationDataState.Failed ? null : summary.ModifiedFileCount; + diagnostics.ModifiedFolderCount = diagnostics.ModifiedPathsState == HydrationDataState.Failed ? null : summary.ModifiedFolderCount; + diagnostics.FinishPhase(diagnostics.ModifiedPathsState == HydrationDataState.NotStarted ? HydrationDataState.Complete : diagnostics.ModifiedPathsState); cancellationToken.ThrowIfCancellationRequested(); - int placeholderFileCount = pathData.PlaceholderFilePaths.Count; - int placeholderFolderCount = pathData.PlaceholderFolderPaths.Count; - int modifiedFileCount = pathData.ModifiedFilePaths.Count; - int modifiedFolderCount = pathData.ModifiedFolderPaths.Count; - - /* Getting the head tree count (used for TotalFolderCount) is potentially slower than the other parts - * of the operation, so we do it last and check that the other parts would succeed before running it. - */ - var soFar = new EnlistmentHydrationSummary() - { - PlaceholderFileCount = placeholderFileCount, - PlaceholderFolderCount = placeholderFolderCount, - ModifiedFileCount = modifiedFileCount, - ModifiedFolderCount = modifiedFolderCount, - TotalFileCount = totalFileCount, - TotalFolderCount = placeholderFolderCount + modifiedFolderCount + 1, // Not calculated yet, use a dummy valid value. - }; - - if (!soFar.IsValid) + // Preserve the early-exit check without reporting its temporary folder total as an observation. + summary.TotalFolderCount = summary.HydratedFolderCount + 1; + if (!summary.IsValid) { - soFar.TotalFolderCount = 0; // Set to default invalid value to avoid confusion with the dummy value above. - tracer.RelatedWarning( - $"Hydration summary early exit: data invalid before tree count. " + - $"TotalFileCount={totalFileCount}, PlaceholderFileCount={placeholderFileCount}, " + - $"ModifiedFileCount={modifiedFileCount}, PlaceholderFolderCount={placeholderFolderCount}, " + - $"ModifiedFolderCount={modifiedFolderCount}"); - EmitDurationTelemetry(tracer, totalStopwatch.ElapsedMilliseconds, indexReadMs, placeholderLoadMs, modifiedPathsLoadMs, treeCountMs: 0, earlyExit: true); - return soFar; + summary.TotalFolderCount = 0; + diagnostics.EarlyExit = true; + diagnostics.Outcome = diagnostics.IndexState == HydrationDataState.Failed + ? HydrationSummaryOutcome.IncompleteData : HydrationSummaryOutcome.InvalidCounts; + return summary; } - /* Get the total folder count from the caller-provided function. - * In the mount process, this comes from the in-memory projection (essentially free). - * In gvfs health --status fallback, this parses the git index via GitIndexProjection. */ cancellationToken.ThrowIfCancellationRequested(); - phaseStopwatch.Restart(); - int totalFolderCount = projectedFolderCountProvider(); - long treeCountMs = phaseStopwatch.ElapsedMilliseconds; - - EmitDurationTelemetry(tracer, totalStopwatch.ElapsedMilliseconds, indexReadMs, placeholderLoadMs, modifiedPathsLoadMs, treeCountMs, earlyExit: false); - - return new EnlistmentHydrationSummary() - { - PlaceholderFileCount = placeholderFileCount, - PlaceholderFolderCount = placeholderFolderCount, - ModifiedFileCount = modifiedFileCount, - ModifiedFolderCount = modifiedFolderCount, - TotalFileCount = totalFileCount, - TotalFolderCount = totalFolderCount, - }; + diagnostics.StartPhase(HydrationSummaryPhase.FolderCount); + summary.TotalFolderCount = projectedFolderCountProvider(); + diagnostics.TotalFolderCount = summary.TotalFolderCount; + diagnostics.FinishPhase(HydrationDataState.Complete); + diagnostics.Outcome = !summary.IsValid || (diagnostics.GetValidationFailures() & ~HydrationValidationFailure.MissingCounts) != HydrationValidationFailure.None ? HydrationSummaryOutcome.InvalidCounts + : diagnostics.CountsComplete ? HydrationSummaryOutcome.Success : HydrationSummaryOutcome.IncompleteData; + return summary; } - catch (OperationCanceledException) + catch (OperationCanceledException e) { - tracer.RelatedInfo($"Hydration summary cancelled after {totalStopwatch.ElapsedMilliseconds}ms"); - return new EnlistmentHydrationSummary() - { - PlaceholderFileCount = -1, - PlaceholderFolderCount = -1, - ModifiedFileCount = -1, - ModifiedFolderCount = -1, - TotalFileCount = -1, - TotalFolderCount = -1, - }; + diagnostics.Outcome = HydrationSummaryOutcome.Cancelled; + diagnostics.CancellationRequested = cancellationToken.IsCancellationRequested; + diagnostics.ExceptionType = e.GetType().FullName; + diagnostics.ExceptionHResult = e.HResult; + diagnostics.FinishPhase(HydrationDataState.Cancelled); + CapturePartialCounts(pathData, diagnostics); + summary.InvalidateCounts(); + return summary; } catch (Exception e) { - tracer.RelatedError($"Hydration summary failed with exception after {totalStopwatch.ElapsedMilliseconds}ms: {e.Message}"); - return new EnlistmentHydrationSummary() - { - PlaceholderFileCount = -1, - PlaceholderFolderCount = -1, - ModifiedFileCount = -1, - ModifiedFolderCount = -1, - TotalFileCount = -1, - TotalFolderCount = -1, - Error = e, - }; + diagnostics.Outcome = HydrationSummaryOutcome.Failed; + diagnostics.ExceptionType = e.GetType().FullName; + diagnostics.ExceptionHResult = e.HResult; + diagnostics.FinishPhase(HydrationDataState.Failed); + CapturePartialCounts(pathData, diagnostics); + + tracer.RelatedWarning(new EventMetadata { ["Exception"] = e.ToString() }, "Hydration summary calculation failed.", Keywords.None); + summary.Error = e; + summary.InvalidateCounts(); + return summary; + } + finally + { + diagnostics.TotalMs = totalStopwatch.ElapsedMilliseconds; + diagnostics.IsValid = summary.IsValid; + tracer.RelatedEvent( + diagnostics.Outcome == HydrationSummaryOutcome.Success || diagnostics.Outcome == HydrationSummaryOutcome.Cancelled + ? EventLevel.Informational : EventLevel.Warning, + "HydrationSummaryDuration", + diagnostics.GetMetadata(), + Keywords.Telemetry); } } - private static void EmitDurationTelemetry( - ITracer tracer, - long totalMs, - long indexReadMs, - long placeholderLoadMs, - long modifiedPathsLoadMs, - long treeCountMs, - bool earlyExit) + private static void CapturePartialCounts(EnlistmentPathData pathData, HydrationSummaryDiagnostics diagnostics) { - EventMetadata metadata = new EventMetadata(); - metadata["TotalMs"] = totalMs; - metadata["IndexReadMs"] = indexReadMs; - metadata["PlaceholderLoadMs"] = placeholderLoadMs; - metadata["ModifiedPathsLoadMs"] = modifiedPathsLoadMs; - metadata["TreeCountMs"] = treeCountMs; - metadata["EarlyExit"] = earlyExit; - tracer.RelatedEvent( - EventLevel.Informational, - "HydrationSummaryDuration", - metadata, - Keywords.Telemetry); + if (diagnostics.Phase == HydrationSummaryPhase.Placeholders + && (pathData.PlaceholderFilePaths.Count > 0 || pathData.PlaceholderFolderPaths.Count > 0)) + { + diagnostics.PlaceholderFileCount = pathData.PlaceholderFilePaths.Count; + diagnostics.PlaceholderFolderCount = pathData.PlaceholderFolderPaths.Count; + if (diagnostics.PlaceholderState == HydrationDataState.Failed) + { + diagnostics.PlaceholderState = HydrationDataState.Partial; + } + } + + if (diagnostics.Phase == HydrationSummaryPhase.ModifiedPaths + && (pathData.ModifiedFilePaths.Count > 0 || pathData.ModifiedFolderPaths.Count > 0)) + { + diagnostics.ModifiedFileCount = pathData.ModifiedFilePaths.Count; + diagnostics.ModifiedFolderCount = pathData.ModifiedFolderPaths.Count; + if (diagnostics.ModifiedPathsState == HydrationDataState.Failed) + { + diagnostics.ModifiedPathsState = HydrationDataState.Partial; + } + } } /// /// Get the total number of files in the index. /// - internal static int GetIndexFileCount(GVFSEnlistment enlistment, PhysicalFileSystem fileSystem) + internal static int GetIndexFileCount(GVFSEnlistment enlistment, PhysicalFileSystem fileSystem, HydrationSummaryDiagnostics diagnostics = null) { string indexPath = enlistment.GitIndexPath; using (var indexFile = fileSystem.OpenFileStream(indexPath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite, callFlushFileBuffers: false)) { + if (diagnostics != null) + { + diagnostics.IndexLength = indexFile.Length; + } + if (indexFile.Length < 12) { + if (diagnostics != null) + { + diagnostics.IndexReadReason = "ShortIndex"; + } + return -1; } - /* The number of files in the index is a big-endian integer from - * the 4 bytes at offsets 8-11 of the index file. */ - indexFile.Position = 8; - var bytes = new byte[4]; - indexFile.ReadExactly( - bytes, // Destination buffer - offset: 0, // Offset in destination buffer, not in indexFile - count: 4); - if (BitConverter.IsLittleEndian) + byte[] header = new byte[12]; + indexFile.ReadExactly(header, 0, header.Length); + int count = System.Buffers.Binary.BinaryPrimitives.ReadInt32BigEndian(header.AsSpan(8, 4)); + if (diagnostics != null) { - Array.Reverse(bytes); + diagnostics.IndexVersion = System.Buffers.Binary.BinaryPrimitives.ReadInt32BigEndian(header.AsSpan(4, 4)); + diagnostics.IndexSignatureValid = header[0] == 'D' && header[1] == 'I' && header[2] == 'R' && header[3] == 'C'; + diagnostics.IndexReadReason = count < 0 ? "NegativeEntryCount" : "Success"; } - int count = BitConverter.ToInt32(bytes, 0); + return count; } } + private void InvalidateCounts() + { + this.PlaceholderFileCount = -1; + this.PlaceholderFolderCount = -1; + this.ModifiedFileCount = -1; + this.ModifiedFolderCount = -1; + this.TotalFileCount = -1; + this.TotalFolderCount = -1; + } } } diff --git a/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs b/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs index d56cfc8bd0..ed76e811d1 100644 --- a/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs +++ b/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs @@ -49,19 +49,37 @@ public void NormalizeAllPaths() /// Goes to the SQLite database for the placeholder lists /// /// The current GVFS enlistment being operated on - public void LoadPlaceholdersFromDatabase(GVFSEnlistment enlistment) + public virtual void LoadPlaceholdersFromDatabase(GVFSEnlistment enlistment, HydrationSummaryDiagnostics diagnostics = null) { - List filePlaceholders = new List(); - List folderPlaceholders = new List(); + this.ReadPlaceholderEntries(enlistment, out List filePlaceholders, out List folderPlaceholders); - using (GVFSDatabase database = new GVFSDatabase(new PhysicalFileSystem(), enlistment.DotGVFSRoot, new SqliteDatabase())) + this.PlaceholderFilePaths.AddRange(filePlaceholders.Select(placeholderData => placeholderData.Path)); + if (diagnostics != null) { - PlaceholderTable placeholderTable = new PlaceholderTable(database); - placeholderTable.GetAllEntries(out filePlaceholders, out folderPlaceholders); + diagnostics.PartialFolderCount = 0; + diagnostics.ExpandedFolderCount = 0; + diagnostics.PossibleTombstoneFolderCount = 0; } - this.PlaceholderFilePaths.AddRange(filePlaceholders.Select(placeholderData => placeholderData.Path)); - this.PlaceholderFolderPaths.AddRange(folderPlaceholders.Select(placeholderData => placeholderData.Path)); + foreach (IPlaceholderData placeholder in folderPlaceholders) + { + this.PlaceholderFolderPaths.Add(placeholder.Path); + if (diagnostics != null) + { + if (placeholder.IsExpandedFolder) + { + diagnostics.ExpandedFolderCount++; + } + else if (placeholder.IsPossibleTombstoneFolder) + { + diagnostics.PossibleTombstoneFolderCount++; + } + else + { + diagnostics.PartialFolderCount++; + } + } + } } /// @@ -95,10 +113,15 @@ public void LoadPathsFromGitIndex(GVFSEnlistment enlistment) this.GitTrackingPaths.AddRange(skipWorktreeFiles); } - public void LoadModifiedPaths(GVFSEnlistment enlistment, ITracer tracer) + public virtual void LoadModifiedPaths(GVFSEnlistment enlistment, ITracer tracer, HydrationSummaryDiagnostics diagnostics = null) { - if (TryLoadModifiedPathsFromPipe(enlistment, tracer)) + if (TryLoadModifiedPathsFromPipe(enlistment, tracer, diagnostics)) { + if (diagnostics != null) + { + diagnostics.ModifiedPathsState = HydrationDataState.Complete; + } + return; } @@ -106,19 +129,54 @@ public void LoadModifiedPaths(GVFSEnlistment enlistment, ITracer tracer) string filePath = Path.Combine(enlistment.DotGVFSRoot, GVFSConstants.DotGVFS.Databases.ModifiedPaths); try { - using (FileStream file = File.Open(filePath, FileMode.OpenOrCreate, FileAccess.Read, FileShare.Read)) - using (StreamReader reader = new StreamReader(file)) + AddModifiedPaths(this.ReadModifiedPathsFile(filePath, diagnostics)); + if (diagnostics != null) { - AddModifiedPaths(ReadModifiedPathDatabaseLines(reader)); + diagnostics.ModifiedPathsDiskOutcome = HydrationPathSourceOutcome.Success; + diagnostics.ModifiedPathsState = HydrationDataState.Complete; } } catch (Exception ex) { - tracer.RelatedWarning($"Failed to read modified paths file at {filePath}: {ex.Message}"); + if (diagnostics != null) + { + diagnostics.ModifiedPathsDiskOutcome = HydrationPathSourceOutcome.Failed; + diagnostics.ModifiedPathsState = this.ModifiedFilePaths.Count > 0 || this.ModifiedFolderPaths.Count > 0 + ? HydrationDataState.Partial : HydrationDataState.Failed; + diagnostics.ModifiedPathsExceptionType = ex.GetType().FullName; + diagnostics.ModifiedPathsExceptionHResult = ex.HResult; + } + + tracer.RelatedWarning($"Failed to read modified paths file at {filePath}: {ex}"); + } + } + + protected virtual void ReadPlaceholderEntries(GVFSEnlistment enlistment, out List files, out List folders) + { + using (GVFSDatabase database = new GVFSDatabase(new PhysicalFileSystem(), enlistment.DotGVFSRoot, new SqliteDatabase())) + { + new PlaceholderTable(database).GetAllEntries(out files, out folders); } } - private IEnumerable ReadModifiedPathDatabaseLines(StreamReader r) + protected virtual IEnumerable ReadModifiedPathsFile(string filePath, HydrationSummaryDiagnostics diagnostics) + { + using (FileStream file = File.Open(filePath, FileMode.OpenOrCreate, FileAccess.Read, FileShare.Read)) + using (StreamReader reader = new StreamReader(file)) + { + foreach (string path in this.ReadModifiedPathDatabaseLines(reader, diagnostics)) + { + yield return path; + } + } + } + + protected virtual NamedPipeClient CreateModifiedPathsPipeClient(GVFSEnlistment enlistment) + { + return new NamedPipeClient(enlistment.NamedPipeName); + } + + internal IEnumerable ReadModifiedPathDatabaseLines(StreamReader r, HydrationSummaryDiagnostics diagnostics = null) { while (!r.EndOfStream) { @@ -131,8 +189,25 @@ private IEnumerable ReadModifiedPathDatabaseLines(StreamReader r) const string LinePrefix = "A "; if (line.StartsWith(LinePrefix)) { + if (diagnostics != null) + { + diagnostics.ModifiedPathsAddRecords++; + } + line = line.Substring(LinePrefix.Length); } + else if (diagnostics != null) + { + if (line.StartsWith("D ")) + { + diagnostics.ModifiedPathsDeleteRecords++; + } + else + { + diagnostics.ModifiedPathsOtherRecords++; + } + } + yield return line; } } @@ -143,14 +218,22 @@ private IEnumerable ReadModifiedPathDatabaseLines(StreamReader r) /// If/when modified paths are moved to SQLite go there instead /// The enlistment being operated on /// An array containing all of the modified paths in string format - private bool TryLoadModifiedPathsFromPipe(GVFSEnlistment enlistment, ITracer tracer) + private bool TryLoadModifiedPathsFromPipe(GVFSEnlistment enlistment, ITracer tracer, HydrationSummaryDiagnostics diagnostics) { - using (NamedPipeClient pipeClient = new NamedPipeClient(enlistment.NamedPipeName)) + using (NamedPipeClient pipeClient = this.CreateModifiedPathsPipeClient(enlistment)) { string[] modifiedPathsList = Array.Empty(); - if (!pipeClient.Connect()) + if (!pipeClient.Connect(timeoutMilliseconds: 3000, out Exception connectError)) { + if (diagnostics != null) + { + diagnostics.ModifiedPathsPipeOutcome = connectError is TimeoutException + ? HydrationPathSourceOutcome.ConnectTimeout : HydrationPathSourceOutcome.ConnectFailed; + diagnostics.ModifiedPathsPipeExceptionType = connectError?.GetType().FullName; + diagnostics.ModifiedPathsPipeExceptionHResult = connectError?.HResult; + } + return false; } @@ -162,6 +245,14 @@ private bool TryLoadModifiedPathsFromPipe(GVFSEnlistment enlistment, ITracer tra NamedPipeMessages.Message modifiedPathsResponse = pipeClient.ReadResponse(); if (!modifiedPathsResponse.Header.Equals(NamedPipeMessages.ModifiedPaths.SuccessResult)) { + if (diagnostics != null) + { + diagnostics.ModifiedPathsPipeOutcome = modifiedPathsResponse.Header == NamedPipeMessages.MountNotReadyResult + ? HydrationPathSourceOutcome.MountNotReady + : modifiedPathsResponse.Header == NamedPipeMessages.ModifiedPaths.InvalidVersion + ? HydrationPathSourceOutcome.InvalidVersion : HydrationPathSourceOutcome.UnexpectedResponse; + } + return false; } @@ -169,11 +260,23 @@ private bool TryLoadModifiedPathsFromPipe(GVFSEnlistment enlistment, ITracer tra } catch (Exception ex) { - tracer.RelatedWarning($"Failed to load modified paths via named pipe: {ex.Message}"); + if (diagnostics != null) + { + diagnostics.ModifiedPathsPipeOutcome = HydrationPathSourceOutcome.Failed; + diagnostics.ModifiedPathsPipeExceptionType = ex.GetType().FullName; + diagnostics.ModifiedPathsPipeExceptionHResult = ex.HResult; + } + + tracer.RelatedWarning($"Failed to load modified paths via named pipe: {ex}"); return false; } AddModifiedPaths(modifiedPathsList); + if (diagnostics != null) + { + diagnostics.ModifiedPathsPipeOutcome = HydrationPathSourceOutcome.Success; + } + return true; } } diff --git a/GVFS/GVFS.Common/HealthCalculator/HydrationStatusCircuitBreaker.cs b/GVFS/GVFS.Common/HealthCalculator/HydrationStatusCircuitBreaker.cs index 315b4d6063..19392ee6cf 100644 --- a/GVFS/GVFS.Common/HealthCalculator/HydrationStatusCircuitBreaker.cs +++ b/GVFS/GVFS.Common/HealthCalculator/HydrationStatusCircuitBreaker.cs @@ -36,7 +36,7 @@ public HydrationStatusCircuitBreaker( /// Returns true if the hydration status feature should be skipped due to /// too many recent failures. /// - public bool IsDisabled() + public virtual bool IsDisabled() { try { @@ -75,7 +75,7 @@ public bool IsDisabled() /// the circuit breaker trips and returns true. /// Uses exclusive file access to prevent concurrent processes from losing counts. /// - public void RecordFailure() + public virtual void RecordFailure() { try { diff --git a/GVFS/GVFS.Common/HealthCalculator/HydrationSummaryDiagnostics.cs b/GVFS/GVFS.Common/HealthCalculator/HydrationSummaryDiagnostics.cs new file mode 100644 index 0000000000..eecbb7c0c3 --- /dev/null +++ b/GVFS/GVFS.Common/HealthCalculator/HydrationSummaryDiagnostics.cs @@ -0,0 +1,261 @@ +using GVFS.Common.Tracing; +using System; +using System.Diagnostics; + +namespace GVFS.Common +{ + public enum HydrationSummaryOutcome + { + NotStarted, + Success, + InvalidCounts, + IncompleteData, + Cancelled, + Failed, + } + + public enum HydrationDataState + { + NotStarted, + Complete, + Partial, + Failed, + Cancelled, + } + + public enum HydrationSummaryPhase + { + None, + IndexRead, + Placeholders, + ModifiedPaths, + FolderCount, + } + + public enum HydrationFolderCountSource + { + Unknown, + Projection, + IndexParser, + } + + public enum HydrationSummaryCaller + { + Unknown, + BackgroundCache, + HealthFallback, + } + + public enum HydrationPathSourceOutcome + { + NotAttempted, + Success, + ConnectTimeout, + ConnectFailed, + MountNotReady, + InvalidVersion, + UnexpectedResponse, + Failed, + } + + [Flags] + public enum HydrationValidationFailure + { + None = 0, + MissingCounts = 1, + NegativeCounts = 2, + HydratedFilesExceedTotal = 4, + HydratedFoldersExceedTotal = 8, + FileSumOverflow = 16, + FolderSumOverflow = 32, + } + + public sealed class HydrationSummaryDiagnostics + { + private readonly Stopwatch phaseStopwatch = new Stopwatch(); + private bool phaseActive; + + public Guid CalculationId { get; } = Guid.NewGuid(); + public Guid? CommandId { get; set; } + public HydrationSummaryCaller Caller { get; set; } + public HydrationFolderCountSource FolderCountSource { get; set; } + public HydrationSummaryOutcome Outcome { get; internal set; } + public HydrationSummaryPhase Phase { get; private set; } + public HydrationDataState IndexState { get; internal set; } + public HydrationDataState PlaceholderState { get; internal set; } + public HydrationDataState ModifiedPathsState { get; internal set; } + public HydrationDataState FolderCountState { get; internal set; } + public int? PlaceholderFileCount { get; internal set; } + public int? PlaceholderFolderCount { get; internal set; } + public int? ModifiedFileCount { get; internal set; } + public int? ModifiedFolderCount { get; internal set; } + public int? TotalFileCount { get; internal set; } + public int? TotalFolderCount { get; internal set; } + public int? PartialFolderCount { get; internal set; } + public int? ExpandedFolderCount { get; internal set; } + public int? PossibleTombstoneFolderCount { get; internal set; } + public long? IndexLength { get; internal set; } + public int? IndexVersion { get; internal set; } + public bool? IndexSignatureValid { get; internal set; } + public string IndexReadReason { get; internal set; } + public HydrationPathSourceOutcome ModifiedPathsPipeOutcome { get; internal set; } + public HydrationPathSourceOutcome ModifiedPathsDiskOutcome { get; internal set; } + public long ModifiedPathsAddRecords { get; internal set; } + public long ModifiedPathsDeleteRecords { get; internal set; } + public long ModifiedPathsOtherRecords { get; internal set; } + public string ModifiedPathsExceptionType { get; internal set; } + public int? ModifiedPathsExceptionHResult { get; internal set; } + public string ModifiedPathsPipeExceptionType { get; internal set; } + public int? ModifiedPathsPipeExceptionHResult { get; internal set; } + public long? IndexReadMs { get; private set; } + public long? PlaceholderLoadMs { get; private set; } + public long? ModifiedPathsLoadMs { get; private set; } + public long? TreeCountMs { get; private set; } + public long TotalMs { get; internal set; } + public bool EarlyExit { get; internal set; } + public bool? CancellationRequested { get; internal set; } + public bool IsValid { get; internal set; } + public string ExceptionType { get; internal set; } + public int? ExceptionHResult { get; internal set; } + + public bool CountsComplete => + this.IndexState == HydrationDataState.Complete + && this.PlaceholderState == HydrationDataState.Complete + && this.ModifiedPathsState == HydrationDataState.Complete + && this.FolderCountState == HydrationDataState.Complete; + + public HydrationValidationFailure GetValidationFailures() + { + HydrationValidationFailure failures = HydrationValidationFailure.None; + if (!this.PlaceholderFileCount.HasValue || !this.PlaceholderFolderCount.HasValue + || !this.ModifiedFileCount.HasValue || !this.ModifiedFolderCount.HasValue + || !this.TotalFileCount.HasValue || !this.TotalFolderCount.HasValue) + { + failures |= HydrationValidationFailure.MissingCounts; + } + + if (this.PlaceholderFileCount < 0 || this.PlaceholderFolderCount < 0 + || this.ModifiedFileCount < 0 || this.ModifiedFolderCount < 0 + || this.TotalFileCount < 0 || this.TotalFolderCount < 0) + { + failures |= HydrationValidationFailure.NegativeCounts; + } + + long? files = (long?)this.PlaceholderFileCount + this.ModifiedFileCount; + long? folders = (long?)this.PlaceholderFolderCount + this.ModifiedFolderCount; + if (files > this.TotalFileCount) + { + failures |= HydrationValidationFailure.HydratedFilesExceedTotal; + } + + if (folders > this.TotalFolderCount) + { + failures |= HydrationValidationFailure.HydratedFoldersExceedTotal; + } + + if (files > int.MaxValue) + { + failures |= HydrationValidationFailure.FileSumOverflow; + } + + if (folders > int.MaxValue) + { + failures |= HydrationValidationFailure.FolderSumOverflow; + } + + return failures; + } + + public EventMetadata GetMetadata() + { + return new EventMetadata + { + ["SchemaVersion"] = 1, + [nameof(this.CalculationId)] = this.CalculationId.ToString("N"), + [nameof(this.CommandId)] = this.CommandId?.ToString("N"), + [nameof(this.Caller)] = this.Caller, + [nameof(this.Outcome)] = this.Outcome, + [nameof(this.Phase)] = this.Phase, + [nameof(this.IsValid)] = this.IsValid, + [nameof(this.CountsComplete)] = this.CountsComplete, + ["ValidationFailures"] = this.GetValidationFailures(), + [nameof(this.PlaceholderFileCount)] = this.PlaceholderFileCount, + [nameof(this.PlaceholderFolderCount)] = this.PlaceholderFolderCount, + [nameof(this.ModifiedFileCount)] = this.ModifiedFileCount, + [nameof(this.ModifiedFolderCount)] = this.ModifiedFolderCount, + [nameof(this.TotalFileCount)] = this.TotalFileCount, + [nameof(this.TotalFolderCount)] = this.TotalFolderCount, + ["HydratedFileCount"] = (long?)this.PlaceholderFileCount + this.ModifiedFileCount, + ["HydratedFolderCount"] = (long?)this.PlaceholderFolderCount + this.ModifiedFolderCount, + [nameof(this.IndexState)] = this.IndexState, + [nameof(this.PlaceholderState)] = this.PlaceholderState, + [nameof(this.ModifiedPathsState)] = this.ModifiedPathsState, + [nameof(this.FolderCountState)] = this.FolderCountState, + [nameof(this.FolderCountSource)] = this.FolderCountSource, + [nameof(this.IndexLength)] = this.IndexLength, + [nameof(this.IndexVersion)] = this.IndexVersion, + [nameof(this.IndexSignatureValid)] = this.IndexSignatureValid, + [nameof(this.IndexReadReason)] = this.IndexReadReason, + [nameof(this.PartialFolderCount)] = this.PartialFolderCount, + [nameof(this.ExpandedFolderCount)] = this.ExpandedFolderCount, + [nameof(this.PossibleTombstoneFolderCount)] = this.PossibleTombstoneFolderCount, + [nameof(this.ModifiedPathsPipeOutcome)] = this.ModifiedPathsPipeOutcome, + [nameof(this.ModifiedPathsDiskOutcome)] = this.ModifiedPathsDiskOutcome, + [nameof(this.ModifiedPathsAddRecords)] = this.ModifiedPathsAddRecords, + [nameof(this.ModifiedPathsDeleteRecords)] = this.ModifiedPathsDeleteRecords, + [nameof(this.ModifiedPathsOtherRecords)] = this.ModifiedPathsOtherRecords, + [nameof(this.ModifiedPathsExceptionType)] = this.ModifiedPathsExceptionType, + [nameof(this.ModifiedPathsExceptionHResult)] = this.ModifiedPathsExceptionHResult, + [nameof(this.ModifiedPathsPipeExceptionType)] = this.ModifiedPathsPipeExceptionType, + [nameof(this.ModifiedPathsPipeExceptionHResult)] = this.ModifiedPathsPipeExceptionHResult, + [nameof(this.TotalMs)] = this.TotalMs, + [nameof(this.IndexReadMs)] = this.IndexReadMs, + [nameof(this.PlaceholderLoadMs)] = this.PlaceholderLoadMs, + [nameof(this.ModifiedPathsLoadMs)] = this.ModifiedPathsLoadMs, + [nameof(this.TreeCountMs)] = this.TreeCountMs, + [nameof(this.EarlyExit)] = this.EarlyExit, + [nameof(this.CancellationRequested)] = this.CancellationRequested, + [nameof(this.ExceptionType)] = this.ExceptionType, + [nameof(this.ExceptionHResult)] = this.ExceptionHResult, + }; + } + + internal void StartPhase(HydrationSummaryPhase phase) + { + this.Phase = phase; + this.phaseActive = true; + this.phaseStopwatch.Restart(); + } + + internal void FinishPhase(HydrationDataState state) + { + if (!this.phaseActive) + { + return; + } + + long elapsedMs = this.phaseStopwatch.ElapsedMilliseconds; + switch (this.Phase) + { + case HydrationSummaryPhase.IndexRead: + this.IndexReadMs = elapsedMs; + this.IndexState = state; + break; + case HydrationSummaryPhase.Placeholders: + this.PlaceholderLoadMs = elapsedMs; + this.PlaceholderState = state; + break; + case HydrationSummaryPhase.ModifiedPaths: + this.ModifiedPathsLoadMs = elapsedMs; + this.ModifiedPathsState = state; + break; + case HydrationSummaryPhase.FolderCount: + this.TreeCountMs = elapsedMs; + this.FolderCountState = state; + break; + } + + this.phaseActive = false; + } + } +} diff --git a/GVFS/GVFS.Common/NamedPipes/HydrationStatusNamedPipeMessages.cs b/GVFS/GVFS.Common/NamedPipes/HydrationStatusNamedPipeMessages.cs index 99ab4bfbd4..53259fc2cf 100644 --- a/GVFS/GVFS.Common/NamedPipes/HydrationStatusNamedPipeMessages.cs +++ b/GVFS/GVFS.Common/NamedPipes/HydrationStatusNamedPipeMessages.cs @@ -1,4 +1,5 @@ using System; +using System.Globalization; namespace GVFS.Common.NamedPipes { @@ -10,8 +11,80 @@ public static class HydrationStatus public const string SuccessResult = "S"; public const string NotAvailableResult = "NA"; + public enum CacheState + { + NotComputed = 0, + Available = 1, + ProviderUnavailable = 2, + FeatureDisabled = 3, + CircuitBreakerDisabled = 4, + InvalidCounts = 5, + IncompleteData = 6, + Cancelled = 7, + Failed = 8, + } + + public enum ParseOutcome + { + Success, + Empty, + TooFewFields, + InvalidNumber, + InvalidCounts, + } + + public sealed class CacheInfo + { + public CacheState State { get; set; } + public Guid? CalculationId { get; set; } + public long AgeMs { get; set; } = -1; + public bool Invalidated { get; set; } + public bool CountsComplete { get; set; } + + public string ToBody() + { + return string.Join(",", "D1", ((int)this.State).ToString(CultureInfo.InvariantCulture), + this.CalculationId?.ToString("N") ?? "-", this.AgeMs.ToString(CultureInfo.InvariantCulture), + this.Invalidated ? "1" : "0", this.CountsComplete ? "1" : "0"); + } + + public static bool TryParse(string body, out CacheInfo info, bool hasCounts = false) + { + info = null; + if (body == null) + { + return false; + } + + string[] parts = body.Split(','); + int offset = hasCounts ? 6 : 0; + if (parts.Length < offset + 6 || parts[offset] != "D1" + || !int.TryParse(parts[offset + 1], NumberStyles.Integer, CultureInfo.InvariantCulture, out int state) + || !Enum.IsDefined(typeof(CacheState), state) + || (parts[offset + 2] != "-" && !Guid.TryParseExact(parts[offset + 2], "N", out _)) + || !long.TryParse(parts[offset + 3], NumberStyles.Integer, CultureInfo.InvariantCulture, out long ageMs) + || ageMs < -1 + || (parts[offset + 4] != "0" && parts[offset + 4] != "1") + || (parts[offset + 5] != "0" && parts[offset + 5] != "1")) + { + return false; + } + + info = new CacheInfo + { + State = (CacheState)state, + CalculationId = parts[offset + 2] == "-" ? null : Guid.ParseExact(parts[offset + 2], "N"), + AgeMs = ageMs, + Invalidated = parts[offset + 4] == "1", + CountsComplete = parts[offset + 5] == "1", + }; + return true; + } + } + /// /// Wire format: PlaceholderFileCount,PlaceholderFolderCount,ModifiedFileCount,ModifiedFolderCount,TotalFileCount,TotalFolderCount + /// An optional D1 extension follows the six counts. CacheInfo defines the extension fields. /// public class Response { @@ -45,20 +118,27 @@ public string ToDisplayMessage() return $"{filePercent}% of files and {folderPercent}% of folders hydrated. Run 'gvfs health' at the repository root for details."; } - public string ToBody() + public string ToBody(CacheInfo info = null) { - return string.Join(",", + string counts = string.Join(",", this.PlaceholderFileCount, this.PlaceholderFolderCount, this.ModifiedFileCount, this.ModifiedFolderCount, this.TotalFileCount, this.TotalFolderCount); + return info == null ? counts : counts + "," + info.ToBody(); } public static bool TryParse(string body, out Response response) + { + return TryParse(body, out response, out _); + } + + public static bool TryParse(string body, out Response response, out ParseOutcome outcome) { response = null; + outcome = ParseOutcome.Empty; if (string.IsNullOrEmpty(body)) { return false; @@ -67,6 +147,7 @@ public static bool TryParse(string body, out Response response) string[] parts = body.Split(','); if (parts.Length < 6) { + outcome = ParseOutcome.TooFewFields; return false; } @@ -77,6 +158,7 @@ public static bool TryParse(string body, out Response response) || !int.TryParse(parts[4], out int totalFileCount) || !int.TryParse(parts[5], out int totalFolderCount)) { + outcome = ParseOutcome.InvalidNumber; return false; } @@ -90,6 +172,7 @@ public static bool TryParse(string body, out Response response) TotalFolderCount = totalFolderCount, }; + outcome = response.IsValid ? ParseOutcome.Success : ParseOutcome.InvalidCounts; return response.IsValid; } } diff --git a/GVFS/GVFS.Common/NamedPipes/NamedPipeClient.cs b/GVFS/GVFS.Common/NamedPipes/NamedPipeClient.cs index 18745788fa..54c282ae49 100644 --- a/GVFS/GVFS.Common/NamedPipes/NamedPipeClient.cs +++ b/GVFS/GVFS.Common/NamedPipes/NamedPipeClient.cs @@ -18,6 +18,12 @@ public NamedPipeClient(string pipeName) public bool Connect(int timeoutMilliseconds = 3000) { + return this.Connect(timeoutMilliseconds, out _); + } + + public virtual bool Connect(int timeoutMilliseconds, out Exception error) + { + error = null; if (this.clientStream != null) { throw new InvalidOperationException(); @@ -28,12 +34,14 @@ public bool Connect(int timeoutMilliseconds = 3000) this.clientStream = new NamedPipeClientStream(this.pipeName); this.clientStream.Connect(timeoutMilliseconds); } - catch (TimeoutException) + catch (TimeoutException ex) { + error = ex; return false; } - catch (IOException) + catch (IOException ex) { + error = ex; return false; } @@ -57,7 +65,7 @@ public bool TrySendRequest(NamedPipeMessages.Message message) return false; } - public void SendRequest(NamedPipeMessages.Message message) + public virtual void SendRequest(NamedPipeMessages.Message message) { this.SendRequest(message.ToString()); } @@ -94,7 +102,7 @@ public string ReadRawResponse() } } - public NamedPipeMessages.Message ReadResponse() + public virtual NamedPipeMessages.Message ReadResponse() { return NamedPipeMessages.Message.FromString(this.ReadRawResponse()); } @@ -113,7 +121,7 @@ public bool TryReadResponse(out NamedPipeMessages.Message message) } } - public void Dispose() + public virtual void Dispose() { this.ValidateConnection(); diff --git a/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs b/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs index 69e50d3fae..b293898104 100644 --- a/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs +++ b/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs @@ -16,7 +16,7 @@ public class TelemetryDaemonEventListener : EventListener, IQueuedPipeStringWrit private QueuedPipeStringWriter pipeWriter; - private TelemetryDaemonEventListener( + internal TelemetryDaemonEventListener( string providerName, string enlistmentId, string mountId, diff --git a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs index e469991750..f8c122861b 100644 --- a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs +++ b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs @@ -8,6 +8,9 @@ using System.Globalization; using System.IO; using System.Text.RegularExpressions; +using System.Linq; +using System.Text.Json; +using System.Threading; namespace GVFS.FunctionalTests.Tests.EnlistmentPerFixture { @@ -137,6 +140,110 @@ public void FilterIntoDirectory() enlistmentHealthStatus: "Highly Hydrated"); } + [TestCase(0), Order(5)] + [TestCase(5)] + public void StatusRecordsTheDisplayedResultAndFallbackDiagnostics(int backoffSeconds) + { + this.RemountWithHydrationStatus(false, backoffSeconds); + JsonElement root = this.WaitForHydrationCacheState("FeatureDisabled", out string output, out string[] lines); + Assert.AreEqual("Status", root.GetProperty("Mode").GetString()); + Guid.ParseExact(root.GetProperty("CommandId").GetString(), "N").ShouldNotEqual(Guid.Empty); + JsonElement cache = root.GetProperty("Cache"); + cache.GetProperty("Outcome").GetString().ShouldEqual("NotAvailable"); + cache.GetProperty("DiagnosticsStatus").GetString().ShouldEqual("Parsed"); + Assert.IsTrue(cache.GetProperty("DiagnosticsAvailable").GetBoolean()); + cache.GetProperty("State").GetString().ShouldEqual("FeatureDisabled"); + string displayOutcome = root.GetProperty("DisplayOutcome").GetString(); + output.ShouldContain(displayOutcome == "Percentage" ? "% of files and " : "Error calculating hydration summary."); + root.GetProperty("ResultSource").GetString().ShouldEqual("Fallback"); + string calculation = lines.Single(line => line.Contains("HydrationSummaryDuration ")); + using (JsonDocument calculationDocument = JsonDocument.Parse(calculation.Substring(calculation.IndexOf('{')))) + { + JsonElement summary = calculationDocument.RootElement; + summary.GetProperty("CommandId").GetString().ShouldEqual(root.GetProperty("CommandId").GetString()); + summary.GetProperty("CalculationId").GetString().ShouldEqual(root.GetProperty("CalculationId").GetString()); + summary.GetProperty("FolderCountSource").GetString().ShouldEqual("IndexParser"); + Assert.AreEqual(JsonValueKind.Number, summary.GetProperty("TotalFileCount").ValueKind); + Assert.AreEqual(JsonValueKind.Number, summary.GetProperty("PlaceholderFolderCount").ValueKind); + } + } + + [TestCase, Order(6)] + public void DetailedHealthRecordsItsCommandMode() + { + HashSet previous = new HashSet(Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log")); + this.Enlistment.Health(); + using (JsonDocument completion = this.ReadHealthCompletion(previous, out _)) + { + completion.RootElement.GetProperty("Mode").GetString().ShouldEqual("Detailed"); + completion.RootElement.GetProperty("Outcome").GetString().ShouldEqual("Success"); + Assert.IsFalse(completion.RootElement.TryGetProperty("Cache", out _)); + } + } + + [TestCase, Order(7)] + public void CachedStatusRecordsThePublishedCalculationIdentity() + { + this.RemountWithHydrationStatus(true); + JsonElement root = this.WaitForHydrationCacheState("Available", out string output, out _); + root.GetProperty("ResultSource").GetString().ShouldEqual("Cache"); + JsonElement cache = root.GetProperty("Cache"); + cache.GetProperty("Outcome").GetString().ShouldEqual("Success"); + cache.GetProperty("DiagnosticsStatus").GetString().ShouldEqual("Parsed"); + cache.GetProperty("State").GetString().ShouldEqual("Available"); + Assert.IsTrue(cache.GetProperty("CountsComplete").GetBoolean()); + Assert.That(cache.GetProperty("AgeMs").GetInt64(), Is.GreaterThanOrEqualTo(0)); + Guid.ParseExact(cache.GetProperty("CalculationId").GetString(), "N").ShouldNotEqual(Guid.Empty); + root.GetProperty("CalculationId").GetString().ShouldEqual(cache.GetProperty("CalculationId").GetString()); + root.GetProperty("Outcome").GetString().ShouldEqual("Success"); + root.GetProperty("CalculationOutcome").GetString().ShouldEqual("Success"); + output.ShouldContain("% of files and "); + } + + private JsonElement WaitForHydrationCacheState(string expectedState, out string output, out string[] lines) + { + Stopwatch deadline = Stopwatch.StartNew(); + string lastCompletion = string.Empty; + output = string.Empty; + lines = Array.Empty(); + while (deadline.Elapsed < TimeSpan.FromSeconds(30)) + { + HashSet previous = new HashSet(Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log")); + output = this.Enlistment.Health(statusOnly: true); + using (JsonDocument completion = this.ReadHealthCompletion(previous, out lines)) + { + JsonElement root = completion.RootElement; + lastCompletion = root.GetRawText(); + if (root.GetProperty("Cache").GetProperty("State").GetString() == expectedState) + { + return root.Clone(); + } + } + + Thread.Sleep(100); + } + + throw new AssertionException("The hydration cache did not reach " + expectedState + ". Last completion: " + lastCompletion); + } + + private void RemountWithHydrationStatus(bool enabled, int backoffSeconds = 2) + { + this.Enlistment.UnmountGVFS(); + GitProcess.InvokeProcess(this.Enlistment.RepoRoot, "config --local gvfs.show-hydration-status " + (enabled ? "true" : "false")).ExitCode.ShouldEqual(0); + GitProcess.InvokeProcess(this.Enlistment.RepoRoot, "config --local gvfs.status-cache-backoff-seconds " + backoffSeconds).ExitCode.ShouldEqual(0); + this.Enlistment.MountGVFS(); + GitProcess.InvokeProcess(this.Enlistment.RepoRoot, "status --porcelain").ExitCode.ShouldEqual(0); + this.Enlistment.WaitForBackgroundOperations(); + } + + private JsonDocument ReadHealthCompletion(HashSet previous, out string[] lines) + { + string log = Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log").Single(path => !previous.Contains(path)); + lines = File.ReadAllLines(log); + string line = lines.Single(value => value.Contains("health (Stop)")); + return JsonDocument.Parse(line.Substring(line.IndexOf('{'))); + } + private void HydratePlaceholder(string filePath) { File.ReadAllText(filePath); diff --git a/GVFS/GVFS.FunctionalTests/Tools/GVFSFunctionalTestEnlistment.cs b/GVFS/GVFS.FunctionalTests/Tools/GVFSFunctionalTestEnlistment.cs index d352a53191..5a3f34b4b0 100644 --- a/GVFS/GVFS.FunctionalTests/Tools/GVFSFunctionalTestEnlistment.cs +++ b/GVFS/GVFS.FunctionalTests/Tools/GVFSFunctionalTestEnlistment.cs @@ -360,9 +360,9 @@ public string Status(string trace = null) return this.gvfsProcess.Status(trace); } - public string Health(string directory = null) + public string Health(string directory = null, bool statusOnly = false) { - return this.gvfsProcess.Health(directory); + return this.gvfsProcess.Health(directory, statusOnly); } public bool WaitForBackgroundOperations(int maxWaitMilliseconds = DefaultMaxWaitMSForStatusCheck) diff --git a/GVFS/GVFS.FunctionalTests/Tools/GVFSProcess.cs b/GVFS/GVFS.FunctionalTests/Tools/GVFSProcess.cs index 7e632a279b..12d8d4c44c 100644 --- a/GVFS/GVFS.FunctionalTests/Tools/GVFSProcess.cs +++ b/GVFS/GVFS.FunctionalTests/Tools/GVFSProcess.cs @@ -179,8 +179,13 @@ public string Status(string trace = null) return this.CallGVFS("status " + this.enlistmentRoot, trace: trace); } - public string Health(string directory = null) + public string Health(string directory = null, bool statusOnly = false) { + if (statusOnly) + { + return this.CallGVFS("health --status \"" + this.enlistmentRoot + '"'); + } + if (string.IsNullOrEmpty(directory)) { return this.CallGVFS("health \"" + this.enlistmentRoot + '"'); diff --git a/GVFS/GVFS.Mount/InProcessMount.cs b/GVFS/GVFS.Mount/InProcessMount.cs index 0a5c930b5f..957a705347 100644 --- a/GVFS/GVFS.Mount/InProcessMount.cs +++ b/GVFS/GVFS.Mount/InProcessMount.cs @@ -768,7 +768,8 @@ private void HandleRequest(ITracer tracer, string request, NamedPipeServer.Conne private void HandleGetHydrationStatusRequest(NamedPipeServer.Connection connection) { - EnlistmentHydrationSummary summary = this.fileSystemCallbacks?.GetCachedHydrationSummary(); + NamedPipeMessages.HydrationStatus.CacheInfo info = new NamedPipeMessages.HydrationStatus.CacheInfo(); + EnlistmentHydrationSummary summary = this.fileSystemCallbacks?.GetCachedHydrationSummary(out info); if (summary == null || !summary.IsValid) { this.tracer.RelatedInfo( @@ -776,7 +777,7 @@ private void HandleGetHydrationStatusRequest(NamedPipeServer.Connection connecti (summary == null ? "No cached hydration summary available yet" : "Cached hydration summary is invalid")); connection.TrySendResponse( - new NamedPipeMessages.Message(NamedPipeMessages.HydrationStatus.NotAvailableResult, null)); + new NamedPipeMessages.Message(NamedPipeMessages.HydrationStatus.NotAvailableResult, info.ToBody())); return; } @@ -791,7 +792,7 @@ private void HandleGetHydrationStatusRequest(NamedPipeServer.Connection connecti }; connection.TrySendResponse( - new NamedPipeMessages.Message(NamedPipeMessages.HydrationStatus.SuccessResult, response.ToBody())); + new NamedPipeMessages.Message(NamedPipeMessages.HydrationStatus.SuccessResult, response.ToBody(info))); } private void HandleDehydrateFolders(NamedPipeMessages.Message message, NamedPipeServer.Connection connection) diff --git a/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs b/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs index 3920ab1354..99ead1c816 100644 --- a/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs +++ b/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs @@ -10,6 +10,10 @@ using System.IO; using System.Text; using System.Threading; +using System.Collections.Generic; +using System.Linq; +using System.Text.Json; +using GVFS.UnitTests.Category; using static GVFS.Virtualization.Projection.GitIndexProjection.GitIndexParser; namespace GVFS.UnitTests.Common @@ -321,5 +325,313 @@ public void CreateSummary_CancelledToken_ReturnsInvalidSummary() Assert.IsFalse(result.IsValid); Assert.IsNull(result.Error); } + + [TestCase(20, "Success", "None")] + [TestCase(1, "InvalidCounts", "HydratedFoldersExceedTotal")] + public void CalculationEmitsCountsAndFinalValidity(int folderCount, string outcome, string validationFailures) + { + this.AddIndex(100); + using (JsonTracer tracer = new JsonTracer("test", "test", disableTelemetry: true)) + { + RecordingListener listener = new RecordingListener(Keywords.Telemetry); + tracer.AddEventListener(listener); + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( + this.context.Enlistment, this.fileSystem, tracer, () => folderCount, new TestPathData()); + + TraceEventMessage message = listener.Events.Single(e => e.EventName == "HydrationSummaryDuration"); + Assert.AreEqual(outcome == "Success" ? EventLevel.Informational : EventLevel.Warning, message.Level); + using (JsonDocument json = JsonDocument.Parse(message.Payload)) + { + JsonElement root = json.RootElement; + Assert.AreEqual(outcome, root.GetProperty("Outcome").GetString()); + Assert.AreEqual(validationFailures, root.GetProperty("ValidationFailures").GetString()); + Assert.AreEqual(100, root.GetProperty("TotalFileCount").GetInt32()); + Assert.AreEqual(2, root.GetProperty("PlaceholderFileCount").GetInt32()); + Assert.AreEqual(3, root.GetProperty("ModifiedFileCount").GetInt32()); + Assert.AreEqual(folderCount, root.GetProperty("TotalFolderCount").GetInt32()); + Assert.AreEqual(summary.IsValid, root.GetProperty("IsValid").GetBoolean()); + Assert.IsTrue(root.GetProperty("CountsComplete").GetBoolean()); + Assert.AreNotEqual(Guid.Empty, Guid.Parse(root.GetProperty("CalculationId").GetString())); + } + } + } + + [TestCase(HydrationSummaryPhase.Placeholders)] + [TestCase(HydrationSummaryPhase.ModifiedPaths)] + [TestCase(HydrationSummaryPhase.FolderCount)] + [Category(CategoryConstants.ExceptionExpected)] + public void FailureRetainsEarlierAndPartialCounts(HydrationSummaryPhase phase) + { + this.AddIndex(100); + using (JsonTracer tracer = new JsonTracer("test", "test", disableTelemetry: true)) + { + RecordingListener telemetry = new RecordingListener(Keywords.Telemetry); + RecordingListener local = new RecordingListener(Keywords.Any); + tracer.AddEventListener(telemetry); + tracer.AddEventListener(local); + TestPathData paths = new TestPathData { FailurePhase = phase }; + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( + this.context.Enlistment, this.fileSystem, tracer, + () => throw new IOException("mock:\\private\\folder {secret}"), paths); + + Assert.IsFalse(summary.IsValid); + Assert.AreEqual(HydrationSummaryOutcome.Failed, summary.Diagnostics.Outcome); + Assert.AreEqual(100, summary.Diagnostics.TotalFileCount); + Assert.AreEqual(phase, summary.Diagnostics.Phase); + Assert.AreEqual(HydrationDataState.Complete, summary.Diagnostics.IndexState); + Assert.AreEqual(phase == HydrationSummaryPhase.Placeholders ? HydrationDataState.Partial : HydrationDataState.Complete, summary.Diagnostics.PlaceholderState); + Assert.AreEqual(phase == HydrationSummaryPhase.Placeholders ? HydrationDataState.NotStarted + : phase == HydrationSummaryPhase.ModifiedPaths ? HydrationDataState.Partial : HydrationDataState.Complete, summary.Diagnostics.ModifiedPathsState); + Assert.AreEqual(phase == HydrationSummaryPhase.FolderCount ? HydrationDataState.Failed : HydrationDataState.NotStarted, summary.Diagnostics.FolderCountState); + Assert.IsFalse(summary.Diagnostics.CountsComplete); + Assert.AreEqual(2, summary.Diagnostics.PlaceholderFileCount); + Assert.IsNull(summary.Diagnostics.TotalFolderCount); + if (phase != HydrationSummaryPhase.Placeholders) + { + Assert.AreEqual(3, summary.Diagnostics.ModifiedFileCount); + } + + TraceEventMessage completion = telemetry.Events.Single(e => e.EventName == "HydrationSummaryDuration"); + Assert.AreEqual(EventLevel.Warning, completion.Level); + string payload = completion.Payload; + Assert.That(payload, Does.Not.Contain("secret")); + Assert.That(payload, Does.Contain("System.IO.IOException")); + Assert.That(local.Events.Single(e => e.EventName == "Warning").Payload, Does.Contain("secret")); + Assert.AreEqual(1, telemetry.Events.Count); + } + } + + [TestCase] + public void FailedSourceDoesNotReportZeroAsAvailable() + { + this.AddIndex(100); + TestPathData paths = new TestPathData { ModifiedState = HydrationDataState.Failed, EmptyModifiedPaths = true }; + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( + this.context.Enlistment, this.fileSystem, this.tracer, () => 20, paths); + Assert.IsNull(summary.Diagnostics.ModifiedFileCount); + Assert.IsNull(summary.Diagnostics.ModifiedFolderCount); + Assert.AreEqual(HydrationDataState.Failed, summary.Diagnostics.ModifiedPathsState); + Assert.IsFalse(summary.Diagnostics.CountsComplete); + Assert.AreEqual(HydrationSummaryOutcome.IncompleteData, summary.Diagnostics.Outcome); + } + + [TestCase] + public void EmptySourceReportsCollectedZero() + { + this.AddIndex(100); + TestPathData paths = new TestPathData { EmptyModifiedPaths = true }; + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( + this.context.Enlistment, this.fileSystem, this.tracer, () => 20, paths); + Assert.AreEqual(0, summary.Diagnostics.ModifiedFileCount); + Assert.AreEqual(0, summary.Diagnostics.ModifiedFolderCount); + Assert.IsTrue(summary.Diagnostics.CountsComplete); + Assert.AreEqual(HydrationSummaryOutcome.Success, summary.Diagnostics.Outcome); + } + + [TestCase] + public void EarlyExitLeavesFolderCountAndTimingUnavailable() + { + this.AddIndex(0); + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( + this.context.Enlistment, this.fileSystem, this.tracer, () => throw new AssertionException("Folder provider must not run."), new TestPathData()); + Assert.IsTrue(summary.Diagnostics.EarlyExit); + Assert.IsFalse(summary.IsValid); + Assert.AreEqual(HydrationSummaryOutcome.InvalidCounts, summary.Diagnostics.Outcome); + Assert.IsNull(summary.Diagnostics.TotalFolderCount); + Assert.IsNull(summary.Diagnostics.TreeCountMs); + Assert.AreEqual(HydrationDataState.NotStarted, summary.Diagnostics.FolderCountState); + Assert.IsTrue(summary.Diagnostics.GetValidationFailures().HasFlag(HydrationValidationFailure.HydratedFilesExceedTotal)); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void CancellationRetainsSuccessfulObservations() + { + this.AddIndex(100); + using (CancellationTokenSource cts = new CancellationTokenSource()) + { + TestPathData paths = new TestPathData { AfterPlaceholders = cts.Cancel }; + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( + this.context.Enlistment, this.fileSystem, this.tracer, () => 20, paths, cts.Token); + Assert.AreEqual(HydrationSummaryOutcome.Cancelled, summary.Diagnostics.Outcome); + Assert.IsTrue(summary.Diagnostics.CancellationRequested); + Assert.AreEqual(HydrationSummaryPhase.Placeholders, summary.Diagnostics.Phase); + Assert.AreEqual(HydrationDataState.Complete, summary.Diagnostics.PlaceholderState); + Assert.AreEqual(100, summary.Diagnostics.TotalFileCount); + Assert.AreEqual(2, summary.Diagnostics.PlaceholderFileCount); + Assert.IsNull(summary.Diagnostics.ModifiedFileCount); + Assert.AreEqual(HydrationDataState.NotStarted, summary.Diagnostics.ModifiedPathsState); + Assert.IsNull(summary.Error); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void UnrelatedCancellationDoesNotChangeCircuitBreakerPolicy() + { + this.AddIndex(100); + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( + this.context.Enlistment, this.fileSystem, this.tracer, () => throw new OperationCanceledException(), new TestPathData()); + Assert.AreEqual(HydrationSummaryOutcome.Cancelled, summary.Diagnostics.Outcome); + Assert.IsFalse(summary.Diagnostics.CancellationRequested); + Assert.AreEqual(HydrationDataState.Cancelled, summary.Diagnostics.FolderCountState); + Assert.IsNull(summary.Error); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void MissingIndexRecordsFailedFirstPhaseAndUnavailableLaterCounts() + { + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( + this.context.Enlistment, new MissingIndexFileSystem(), this.tracer, () => 20, new TestPathData()); + Assert.AreEqual(HydrationSummaryOutcome.Failed, summary.Diagnostics.Outcome); + Assert.AreEqual(HydrationSummaryPhase.IndexRead, summary.Diagnostics.Phase); + Assert.AreEqual(HydrationDataState.Failed, summary.Diagnostics.IndexState); + Assert.AreEqual(HydrationDataState.NotStarted, summary.Diagnostics.PlaceholderState); + Assert.IsNull(summary.Diagnostics.TotalFileCount); + Assert.IsNull(summary.Diagnostics.PlaceholderFileCount); + Assert.IsNull(summary.Diagnostics.ModifiedFileCount); + Assert.IsNotNull(summary.Diagnostics.IndexReadMs); + Assert.IsNull(summary.Diagnostics.PlaceholderLoadMs); + } + + [TestCase(true, "ShortIndex")] + [TestCase(false, "NegativeEntryCount")] + public void UnavailableIndexTotalIsIncompleteRatherThanArithmeticInvalidity(bool shortIndex, string reason) + { + if (shortIndex) + { + this.enlistmentDirectory.CreateFile(this.context.Enlistment.GitIndexPath, "short"); + } + else + { + this.AddIndex(-1); + } + + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( + this.context.Enlistment, this.fileSystem, this.tracer, () => 20, new TestPathData()); + Assert.AreEqual(HydrationSummaryOutcome.IncompleteData, summary.Diagnostics.Outcome); + Assert.AreEqual(reason, summary.Diagnostics.IndexReadReason); + Assert.AreEqual(HydrationDataState.Failed, summary.Diagnostics.IndexState); + Assert.IsNull(summary.Diagnostics.TotalFileCount); + Assert.IsNull(summary.Diagnostics.TotalFolderCount); + Assert.IsFalse(summary.IsValid); + Assert.AreEqual(HydrationValidationFailure.MissingCounts, summary.Diagnostics.GetValidationFailures()); + } + + [TestCase(true)] + [TestCase(false)] + public void IndexDiagnosticsRecordHeaderWithoutLeakingItsBytes(bool validSignature) + { + this.AddIndex(100, validSignature); + HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics(); + Assert.AreEqual(100, EnlistmentHydrationSummary.GetIndexFileCount(this.context.Enlistment, this.fileSystem, diagnostics)); + Assert.AreEqual(12, diagnostics.IndexLength); + Assert.AreEqual(4, diagnostics.IndexVersion); + Assert.AreEqual(validSignature, diagnostics.IndexSignatureValid); + Assert.AreEqual("Success", diagnostics.IndexReadReason); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void InPhaseCancellationPreservesPartialModifiedCountsAndEmitsInformationalResult() + { + this.AddIndex(100); + using (CancellationTokenSource cts = new CancellationTokenSource()) + using (JsonTracer tracer = new JsonTracer("test", "test", disableTelemetry: true)) + { + RecordingListener listener = new RecordingListener(Keywords.Telemetry); + tracer.AddEventListener(listener); + TestPathData paths = new TestPathData + { + DuringModifiedPaths = () => { cts.Cancel(); cts.Token.ThrowIfCancellationRequested(); }, + }; + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( + this.context.Enlistment, this.fileSystem, tracer, () => 20, paths, cts.Token); + Assert.AreEqual(HydrationSummaryOutcome.Cancelled, summary.Diagnostics.Outcome); + Assert.AreEqual(HydrationDataState.Cancelled, summary.Diagnostics.ModifiedPathsState); + Assert.AreEqual(3, summary.Diagnostics.ModifiedFileCount); + Assert.AreEqual(HydrationSummaryPhase.ModifiedPaths, summary.Diagnostics.Phase); + TraceEventMessage message = listener.Events.Single(e => e.EventName == "HydrationSummaryDuration"); + Assert.AreEqual(EventLevel.Informational, message.Level); + using (JsonDocument json = JsonDocument.Parse(message.Payload)) + { + Assert.AreEqual(JsonValueKind.Null, json.RootElement.GetProperty("TreeCountMs").ValueKind); + } + } + } + + private sealed class MissingIndexFileSystem : GVFS.Common.FileSystem.PhysicalFileSystem + { + public override Stream OpenFileStream(string path, FileMode fileMode, FileAccess fileAccess, FileShare shareMode, FileOptions options, bool flushesToDisk) + { + throw new FileNotFoundException("mock:\\missing\\index"); + } + } + + private void AddIndex(int count, bool validSignature = true) + { + byte[] bytes = new byte[12]; + Encoding.ASCII.GetBytes("DIRC").CopyTo(bytes, 0); + if (!validSignature) + { + bytes[0] = 0xFF; + } + System.Buffers.Binary.BinaryPrimitives.WriteInt32BigEndian(bytes.AsSpan(4, 4), 4); + System.Buffers.Binary.BinaryPrimitives.WriteInt32BigEndian(bytes.AsSpan(8, 4), count); + MockFile file = new MockFile(this.context.Enlistment.GitIndexPath, bytes); + this.enlistmentDirectory.FindDirectory(Path.Combine(this.gitParentPath, ".git")).Files.Add(file.FullName, file); + } + + private sealed class TestPathData : EnlistmentPathData + { + public HydrationSummaryPhase FailurePhase { get; set; } + public HydrationDataState ModifiedState { get; set; } = HydrationDataState.Complete; + public bool EmptyModifiedPaths { get; set; } + public Action AfterPlaceholders { get; set; } + public Action DuringModifiedPaths { get; set; } + + public override void LoadPlaceholdersFromDatabase(GVFSEnlistment enlistment, HydrationSummaryDiagnostics diagnostics = null) + { + this.PlaceholderFilePaths.AddRange(new[] { "a", "b" }); + this.PlaceholderFolderPaths.Add("folder"); + if (this.FailurePhase == HydrationSummaryPhase.Placeholders) + { + throw new IOException("mock:\\private\\placeholder {secret}"); + } + + this.AfterPlaceholders?.Invoke(); + } + + public override void LoadModifiedPaths(GVFSEnlistment enlistment, ITracer tracer, HydrationSummaryDiagnostics diagnostics = null) + { + if (!this.EmptyModifiedPaths) + { + this.ModifiedFilePaths.AddRange(new[] { "c", "d", "e" }); + this.ModifiedFolderPaths.Add("other"); + } + + diagnostics.ModifiedPathsState = this.ModifiedState; + this.DuringModifiedPaths?.Invoke(); + if (this.FailurePhase == HydrationSummaryPhase.ModifiedPaths) + { + throw new IOException("mock:\\private\\modified {secret}"); + } + } + } + + private sealed class RecordingListener : EventListener + { + public RecordingListener(Keywords keywords) : base(EventLevel.Verbose, keywords, null) + { + } + + public List Events { get; } = new List(); + + protected override void RecordMessageInternal(TraceEventMessage message) + { + this.Events.Add(message); + } + } } } diff --git a/GVFS/GVFS.UnitTests/Common/EnlistmentPathDiagnosticsTests.cs b/GVFS/GVFS.UnitTests/Common/EnlistmentPathDiagnosticsTests.cs new file mode 100644 index 0000000000..4c2aed4a68 --- /dev/null +++ b/GVFS/GVFS.UnitTests/Common/EnlistmentPathDiagnosticsTests.cs @@ -0,0 +1,166 @@ +using GVFS.Common; +using GVFS.Common.Database; +using GVFS.Common.NamedPipes; +using GVFS.UnitTests.Category; +using GVFS.UnitTests.Mock.Common; +using NUnit.Framework; +using System; +using System.Collections.Generic; +using System.IO; +using System.Linq; + +namespace GVFS.UnitTests.Common +{ + [TestFixture] + public class EnlistmentPathDiagnosticsTests + { + [TestCase("S", "Success")] + [TestCase("NotReady", "MountNotReady")] + [TestCase("InvalidVersion", "InvalidVersion")] + [TestCase("unknown", "UnexpectedResponse")] + public void RealLoaderRecordsPipeOutcomeAndDiskFallback(string header, string expected) + { + if (header == "NotReady") + { + header = NamedPipeMessages.MountNotReadyResult; + } + else if (header == "InvalidVersion") + { + header = NamedPipeMessages.ModifiedPaths.InvalidVersion; + } + + SourcePathData paths = new SourcePathData(); + paths.Pipe.Response = new NamedPipeMessages.Message(header, "file\0folder/\0"); + HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics(); + using (MockTracer tracer = new MockTracer()) + { + paths.LoadModifiedPaths(CreateEnlistment(), tracer, diagnostics); + } + + Assert.AreEqual(expected, diagnostics.ModifiedPathsPipeOutcome.ToString()); + Assert.AreEqual(HydrationDataState.Complete, diagnostics.ModifiedPathsState); + Assert.AreEqual(expected == "Success" ? HydrationPathSourceOutcome.NotAttempted : HydrationPathSourceOutcome.Success, diagnostics.ModifiedPathsDiskOutcome); + Assert.AreEqual(expected == "Success" ? "file" : "disk-file", paths.ModifiedFilePaths.Single()); + Assert.AreEqual(3000, paths.Pipe.ConnectTimeoutMs); + Assert.IsTrue(paths.Pipe.Disposed); + } + + [TestCase(true, "ConnectTimeout")] + [TestCase(false, "ConnectFailed")] + [Category(CategoryConstants.ExceptionExpected)] + public void ConnectionFailuresRetainCauseAndUseDisk(bool timeout, string expected) + { + SourcePathData paths = new SourcePathData(); + paths.Pipe.ConnectError = timeout ? new TimeoutException("private") : new IOException("private"); + HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics(); + using (MockTracer tracer = new MockTracer()) + { + paths.LoadModifiedPaths(CreateEnlistment(), tracer, diagnostics); + } + + Assert.AreEqual(expected, diagnostics.ModifiedPathsPipeOutcome.ToString()); + Assert.AreEqual(paths.Pipe.ConnectError.GetType().FullName, diagnostics.ModifiedPathsPipeExceptionType); + Assert.AreEqual(paths.Pipe.ConnectError.HResult, diagnostics.ModifiedPathsPipeExceptionHResult); + Assert.AreEqual(HydrationPathSourceOutcome.Success, diagnostics.ModifiedPathsDiskOutcome); + Assert.AreEqual(HydrationDataState.Complete, diagnostics.ModifiedPathsState); + } + + [TestCase(false, "Failed", 0)] + [TestCase(true, "Partial", 1)] + [Category(CategoryConstants.ExceptionExpected)] + public void DiskFailuresRetainCompletenessAndPartialPaths(bool partial, string state, int count) + { + SourcePathData paths = new SourcePathData { FailDisk = true, PartialDisk = partial }; + HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics(); + using (MockTracer tracer = new MockTracer()) + { + paths.LoadModifiedPaths(CreateEnlistment(), tracer, diagnostics); + Assert.That(tracer.RelatedWarningEvents.Single(), Does.Contain("System.IO.IOException")); + } + + Assert.AreEqual(state, diagnostics.ModifiedPathsState.ToString()); + Assert.AreEqual(HydrationPathSourceOutcome.Failed, diagnostics.ModifiedPathsDiskOutcome); + Assert.AreEqual(typeof(IOException).FullName, diagnostics.ModifiedPathsExceptionType); + Assert.IsNotNull(diagnostics.ModifiedPathsExceptionHResult); + Assert.AreEqual(count, paths.ModifiedFilePaths.Count); + } + + [TestCase(true)] + [TestCase(false)] + [Category(CategoryConstants.ExceptionExpected)] + public void PipeSendAndReadExceptionsRetainCause(bool send) + { + SourcePathData paths = new SourcePathData(); + IOException error = new IOException("private"); + paths.Pipe.SendError = send ? error : null; + paths.Pipe.ReadError = send ? null : error; + HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics(); + using (MockTracer tracer = new MockTracer()) + { + paths.LoadModifiedPaths(CreateEnlistment(), tracer, diagnostics); + } + + Assert.AreEqual(HydrationPathSourceOutcome.Failed, diagnostics.ModifiedPathsPipeOutcome); + Assert.AreEqual(typeof(IOException).FullName, diagnostics.ModifiedPathsPipeExceptionType); + Assert.AreEqual(error.HResult, diagnostics.ModifiedPathsPipeExceptionHResult); + Assert.AreEqual(HydrationPathSourceOutcome.Success, diagnostics.ModifiedPathsDiskOutcome); + } + + [TestCase] + public void RealPlaceholderLoaderClassifiesEachFolderKind() + { + SourcePathData paths = new SourcePathData(); + HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics(); + paths.LoadPlaceholdersFromDatabase(CreateEnlistment(), diagnostics); + Assert.AreEqual(1, paths.PlaceholderFilePaths.Count); + Assert.AreEqual(3, paths.PlaceholderFolderPaths.Count); + Assert.AreEqual(1, diagnostics.PartialFolderCount); + Assert.AreEqual(1, diagnostics.ExpandedFolderCount); + Assert.AreEqual(1, diagnostics.PossibleTombstoneFolderCount); + } + + private static GVFSEnlistment CreateEnlistment() + { + return new MockGVFSEnlistment("mock:\\repo", "mock://repo", "mock:\\git", gitProcess: null); + } + + private sealed class SourcePathData : EnlistmentPathData + { + public MockNamedPipeClient Pipe { get; } = new MockNamedPipeClient + { + Response = new NamedPipeMessages.Message("unknown", null), + }; + public bool FailDisk { get; set; } + public bool PartialDisk { get; set; } + + protected override NamedPipeClient CreateModifiedPathsPipeClient(GVFSEnlistment enlistment) + { + return this.Pipe; + } + + protected override IEnumerable ReadModifiedPathsFile(string filePath, HydrationSummaryDiagnostics diagnostics) + { + if (!this.FailDisk || this.PartialDisk) + { + yield return "disk-file"; + } + + if (this.FailDisk) + { + throw new IOException("mock:\\private\\modified-paths"); + } + } + + protected override void ReadPlaceholderEntries(GVFSEnlistment enlistment, out List files, out List folders) + { + files = new List { new PlaceholderTable.PlaceholderData { Path = "file", PathType = PlaceholderTable.PlaceholderData.PlaceholderType.File } }; + folders = new List + { + new PlaceholderTable.PlaceholderData { Path = "partial", PathType = PlaceholderTable.PlaceholderData.PlaceholderType.PartialFolder }, + new PlaceholderTable.PlaceholderData { Path = "expanded", PathType = PlaceholderTable.PlaceholderData.PlaceholderType.ExpandedFolder }, + new PlaceholderTable.PlaceholderData { Path = "tombstone", PathType = PlaceholderTable.PlaceholderData.PlaceholderType.PossibleTombstoneFolder }, + }; + } + } + } +} diff --git a/GVFS/GVFS.UnitTests/Common/GitStatusCacheTests.cs b/GVFS/GVFS.UnitTests/Common/GitStatusCacheTests.cs index 59737a83f8..aa82ec0c81 100644 --- a/GVFS/GVFS.UnitTests/Common/GitStatusCacheTests.cs +++ b/GVFS/GVFS.UnitTests/Common/GitStatusCacheTests.cs @@ -10,6 +10,8 @@ using System; using System.Collections.Generic; using System.IO; +using System.Threading; +using GVFS.Common.Tracing; namespace GVFS.UnitTests.Common { @@ -88,6 +90,244 @@ public void TearDown() GitStatusCache.TEST_EnableHydrationSummaryOverride = null; } + [TestCase] + public void MissingHydrationProviderExplainsTheCacheMiss() + { + using (GitStatusCache cache = new GitStatusCache(this.context, TimeSpan.Zero)) + { + cache.UpdateHydrationSummary(); + Assert.IsNull(cache.GetCachedHydrationSummary(out NamedPipeMessages.HydrationStatus.CacheInfo info)); + Assert.AreEqual(NamedPipeMessages.HydrationStatus.CacheState.ProviderUnavailable, info.State); + Assert.IsNull(info.CalculationId); + Assert.AreEqual(-1, info.AgeMs); + } + } + + [TestCase] + public void DisabledHydrationFeatureExplainsTheCacheMiss() + { + using (GitStatusCache cache = new GitStatusCache(this.context, TimeSpan.Zero)) + { + cache.SetProjectedFolderCountProvider(() => throw new AssertionException("A disabled feature must not count folders.")); + cache.UpdateHydrationSummary(); + Assert.IsNull(cache.GetCachedHydrationSummary(out NamedPipeMessages.HydrationStatus.CacheInfo info)); + Assert.AreEqual(NamedPipeMessages.HydrationStatus.CacheState.FeatureDisabled, info.State); + Assert.IsFalse(info.CountsComplete); + } + } + + [TestCase] + public void HydrationSnapshotPublishesCountsIdentityAgeAndInvalidationTogether() + { + this.AddHydrationIndex(); + using (DiagnosticStatusCache cache = new DiagnosticStatusCache(this.context)) + { + cache.Calculate = diagnostics => this.CalculateHydration(diagnostics); + cache.UpdateHydrationSummary(); + EnlistmentHydrationSummary summary = cache.GetCachedHydrationSummary(out NamedPipeMessages.HydrationStatus.CacheInfo info); + Assert.IsNotNull(summary); + Assert.AreEqual(summary.Diagnostics.CalculationId, info.CalculationId); + Assert.AreEqual(NamedPipeMessages.HydrationStatus.CacheState.Available, info.State); + Assert.IsTrue(info.CountsComplete); + Assert.That(info.AgeMs, Is.GreaterThanOrEqualTo(0)); + Assert.IsFalse(info.Invalidated); + cache.Invalidate(); + Assert.AreSame(summary, cache.GetCachedHydrationSummary(out info)); + Assert.IsTrue(info.Invalidated); + cache.Enabled = false; + cache.UpdateHydrationSummary(); + Assert.AreSame(summary, cache.GetCachedHydrationSummary(out NamedPipeMessages.HydrationStatus.CacheInfo skipped)); + Assert.AreEqual(NamedPipeMessages.HydrationStatus.CacheState.FeatureDisabled, skipped.State); + Assert.AreEqual(info.CalculationId, skipped.CalculationId); + Assert.That(skipped.AgeMs, Is.GreaterThanOrEqualTo(info.AgeMs)); + cache.Enabled = true; + cache.Breaker.Disabled = true; + cache.UpdateHydrationSummary(); + Assert.AreSame(summary, cache.GetCachedHydrationSummary(out info)); + Assert.AreEqual(NamedPipeMessages.HydrationStatus.CacheState.CircuitBreakerDisabled, info.State); + } + } + + [TestCase("InvalidCounts", false)] + [TestCase("IncompleteData", true)] + [TestCase("Cancelled", false)] + [TestCase("Failed", false)] + [Category(CategoryConstants.ExceptionExpected)] + public void HydrationRefreshReportsEachCalculationState(string state, bool available) + { + this.AddHydrationIndex(); + using (DiagnosticStatusCache cache = new DiagnosticStatusCache(this.context)) + using (CancellationTokenSource cancelled = new CancellationTokenSource()) + { + cancelled.Cancel(); + cache.Calculate = diagnostics => this.CalculateHydration(diagnostics); + cache.UpdateHydrationSummary(); + Assert.IsNotNull(cache.GetCachedHydrationSummary(out _)); + cache.Calculate = diagnostics => this.CalculateHydration(diagnostics, + failModified: state == "IncompleteData", + folderCount: state == "InvalidCounts" ? -1 : 20, + throwFolder: state == "Failed", + cancellationToken: state == "Cancelled" ? cancelled.Token : default); + cache.UpdateHydrationSummary(); + EnlistmentHydrationSummary summary = cache.GetCachedHydrationSummary(out NamedPipeMessages.HydrationStatus.CacheInfo info); + Assert.AreEqual(available, summary != null); + Assert.AreEqual(state, info.State.ToString()); + Assert.IsNotNull(info.CalculationId); + Assert.IsFalse(info.CountsComplete && state != "InvalidCounts"); + Assert.AreEqual(state == "Failed" ? 1 : 0, cache.Breaker.Failures); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void ConfigurationFailurePreservesSummaryAndDoesNotTripBreaker() + { + this.AddHydrationIndex(); + using (DiagnosticStatusCache cache = new DiagnosticStatusCache(this.context)) + { + cache.Calculate = diagnostics => this.CalculateHydration(diagnostics); + cache.UpdateHydrationSummary(); + EnlistmentHydrationSummary previous = cache.GetCachedHydrationSummary(out NamedPipeMessages.HydrationStatus.CacheInfo previousInfo); + cache.ThrowConfig = true; + Assert.Throws(() => cache.UpdateHydrationSummary()); + Assert.AreSame(previous, cache.GetCachedHydrationSummary(out NamedPipeMessages.HydrationStatus.CacheInfo info)); + Assert.AreEqual(previousInfo.CalculationId, info.CalculationId); + Assert.AreEqual(NamedPipeMessages.HydrationStatus.CacheState.Available, info.State); + Assert.AreEqual(0, cache.Breaker.Failures); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void UnexpectedCacheUpdateFailureHasExplicitStateAndTripsBreakerOnce() + { + using (DiagnosticStatusCache cache = new DiagnosticStatusCache(this.context)) + { + cache.Calculate = diagnostics => throw new IOException("mock:\\private\\cache"); + cache.UpdateHydrationSummary(); + Assert.IsNull(cache.GetCachedHydrationSummary(out NamedPipeMessages.HydrationStatus.CacheInfo info)); + Assert.AreEqual(NamedPipeMessages.HydrationStatus.CacheState.Failed, info.State); + Assert.AreEqual(1, cache.Breaker.Failures); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void ForeignCancellationDoesNotIncrementTheBreaker() + { + this.AddHydrationIndex(); + using (DiagnosticStatusCache cache = new DiagnosticStatusCache(this.context)) + { + cache.Calculate = diagnostics => EnlistmentHydrationSummary.CreateSummary(this.context.Enlistment, this.fileSystem, this.context.Tracer, + () => throw new OperationCanceledException(), new EmptyHydrationPaths(), diagnostics: diagnostics); + cache.UpdateHydrationSummary(); + Assert.IsNull(cache.GetCachedHydrationSummary(out NamedPipeMessages.HydrationStatus.CacheInfo info)); + Assert.AreEqual(NamedPipeMessages.HydrationStatus.CacheState.Cancelled, info.State); + Assert.AreEqual(0, cache.Breaker.Failures); + } + } + + [TestCase] + public void HeartbeatCountersResetAndCurrentStateIsAPointSample() + { + using (DiagnosticStatusCache cache = new DiagnosticStatusCache(this.context)) + { + cache.Initialize(); + cache.GetCachedHydrationSummary(out _); + cache.GetCachedHydrationSummary(out _); + cache.Enabled = false; + cache.UpdateHydrationSummary(); + EventMetadata metadata = new EventMetadata(); + Assert.IsTrue(cache.WriteTelemetryandReset(metadata)); + Assert.AreEqual(2L, metadata["HydrationStatus.RequestCount"]); + Assert.AreEqual(2L, metadata["HydrationStatus.UnavailableCount"]); + Assert.AreEqual(NamedPipeMessages.HydrationStatus.CacheState.FeatureDisabled, metadata["HydrationStatus.CurrentCacheState"]); + EventMetadata reset = new EventMetadata(); + cache.WriteTelemetryandReset(reset); + Assert.IsFalse(reset.ContainsKey("HydrationStatus.RequestCount")); + } + } + + private void AddHydrationIndex() + { + byte[] bytes = new byte[12]; + System.Text.Encoding.ASCII.GetBytes("DIRC").CopyTo(bytes, 0); + bytes[7] = 4; + bytes[11] = 100; + MockFile file = new MockFile(this.context.Enlistment.GitIndexPath, bytes); + this.enlistmentDirectory.FindDirectory(Path.Combine(this.gitParentPath, ".git")).Files.Add(file.FullName, file); + } + + private EnlistmentHydrationSummary CalculateHydration(HydrationSummaryDiagnostics diagnostics, bool failModified = false, + int folderCount = 20, bool throwFolder = false, CancellationToken cancellationToken = default) + { + return EnlistmentHydrationSummary.CreateSummary(this.context.Enlistment, this.fileSystem, this.context.Tracer, + () => throwFolder ? throw new IOException("mock:\\private\\folder") : folderCount, + new EmptyHydrationPaths { FailModified = failModified }, cancellationToken, diagnostics); + } + + private sealed class EmptyHydrationPaths : EnlistmentPathData + { + public bool FailModified { get; set; } + + public override void LoadPlaceholdersFromDatabase(GVFSEnlistment enlistment, HydrationSummaryDiagnostics diagnostics = null) + { + } + + public override void LoadModifiedPaths(GVFSEnlistment enlistment, ITracer tracer, HydrationSummaryDiagnostics diagnostics = null) + { + diagnostics.ModifiedPathsState = this.FailModified ? HydrationDataState.Failed : HydrationDataState.Complete; + } + } + + private sealed class DiagnosticStatusCache : GitStatusCache + { + public DiagnosticStatusCache(GVFSContext context) : base(context, TimeSpan.Zero) + { + this.SetProjectedFolderCountProvider(() => 20); + } + + public Func Calculate { get; set; } + public bool Enabled { get; set; } = true; + public bool ThrowConfig { get; set; } + public MockHydrationBreaker Breaker { get; } = new MockHydrationBreaker(); + + internal override bool GetHydrationSummaryEnabled() + { + return this.ThrowConfig ? throw new IOException("mock:\\config") : this.Enabled; + } + + internal override HydrationStatusCircuitBreaker CreateHydrationCircuitBreaker() + { + return this.Breaker; + } + + internal override EnlistmentHydrationSummary CreateHydrationSummary(HydrationSummaryDiagnostics diagnostics) + { + return this.Calculate(diagnostics); + } + } + + private sealed class MockHydrationBreaker : HydrationStatusCircuitBreaker + { + public MockHydrationBreaker() : base("mock:\\gvfs", NullTracer.Instance) + { + } + + public bool Disabled { get; set; } + public int Failures { get; private set; } + + public override bool IsDisabled() + { + return this.Disabled; + } + + public override void RecordFailure() + { + this.Failures++; + } + } + [TestCase] public void CanInvalidateCleanCache() { diff --git a/GVFS/GVFS.UnitTests/Common/HydrationStatusDiagnosticsTests.cs b/GVFS/GVFS.UnitTests/Common/HydrationStatusDiagnosticsTests.cs new file mode 100644 index 0000000000..3416b97ca1 --- /dev/null +++ b/GVFS/GVFS.UnitTests/Common/HydrationStatusDiagnosticsTests.cs @@ -0,0 +1,367 @@ +using GVFS.CommandLine; +using GVFS.Common; +using GVFS.Common.NamedPipes; +using GVFS.Common.Tracing; +using GVFS.UnitTests.Mock.Common; +using NUnit.Framework; +using System; +using System.IO; +using System.Linq; +using System.Collections.Generic; +using System.Threading; +using GVFS.UnitTests.Category; + +namespace GVFS.UnitTests.Common +{ + [TestFixture] + public class HydrationStatusDiagnosticsTests + { + [TestCase] + public void CacheExtensionPreservesLegacyCountPrefix() + { + Guid calculationId = Guid.NewGuid(); + NamedPipeMessages.HydrationStatus.Response response = new NamedPipeMessages.HydrationStatus.Response + { + PlaceholderFileCount = 1, + PlaceholderFolderCount = 2, + ModifiedFileCount = 3, + ModifiedFolderCount = 4, + TotalFileCount = 100, + TotalFolderCount = 50, + }; + NamedPipeMessages.HydrationStatus.CacheInfo info = new NamedPipeMessages.HydrationStatus.CacheInfo + { + State = NamedPipeMessages.HydrationStatus.CacheState.Available, + CalculationId = calculationId, + AgeMs = 123, + Invalidated = true, + CountsComplete = true, + }; + string body = response.ToBody(info); + Assert.AreEqual("1,2,3,4,100,50,D1,1," + calculationId.ToString("N") + ",123,1,1", body); + Assert.IsTrue(NamedPipeMessages.HydrationStatus.Response.TryParse(body, out NamedPipeMessages.HydrationStatus.Response parsed)); + Assert.AreEqual(100, parsed.TotalFileCount); + Assert.IsTrue(NamedPipeMessages.HydrationStatus.CacheInfo.TryParse(body, out NamedPipeMessages.HydrationStatus.CacheInfo parsedInfo, hasCounts: true)); + Assert.AreEqual(calculationId, parsedInfo.CalculationId); + Assert.AreEqual(123, parsedInfo.AgeMs); + Assert.IsTrue(parsedInfo.Invalidated); + Assert.IsTrue(parsedInfo.CountsComplete); + } + + [TestCase(null)] + [TestCase("")] + [TestCase("D2,1,-,0,0,1")] + [TestCase("D1,999,-,0,0,1")] + [TestCase("D1,1,private-path,0,0,1")] + [TestCase("D1,1,-,-2,0,1")] + [TestCase("D1,1,-,0,yes,1")] + [TestCase("D1,1,-,0,0,yes")] + public void CacheExtensionRejectsUnknownOrMalformedFields(string body) + { + Assert.IsFalse(NamedPipeMessages.HydrationStatus.CacheInfo.TryParse(body, out _)); + } + + [TestCase(null, "MalformedResponse")] + [TestCase("1,2", "MalformedResponse")] + [TestCase("1,2,secret,4,100,50", "MalformedResponse")] + [TestCase("1,2,3,4,100,1", "InvalidCounts")] + [TestCase("1,2,3,4,100,50", "Success")] + public void CacheResultDistinguishesMalformedAndInvalidCounts(string body, string outcome) + { + HealthVerb.CacheLookupResult result = HealthVerb.ParseCachedResponse( + new NamedPipeMessages.Message("S", body)); + Assert.AreEqual(outcome, result.Outcome.ToString()); + Assert.IsNull(result.Info); + Assert.IsFalse((bool)result.GetMetadata()["DiagnosticsAvailable"]); + Assert.That(EventMetadataConverter.SerializeToString(result.GetMetadata()), Does.Not.Contain("secret")); + if (body != null) + { + Assert.AreEqual(1, result.Counts["PlaceholderFileCount"]); + } + } + + [TestCase] + public void CacheMissRetainsTheFailedCalculationIdentity() + { + NamedPipeMessages.HydrationStatus.CacheInfo info = new NamedPipeMessages.HydrationStatus.CacheInfo + { + State = NamedPipeMessages.HydrationStatus.CacheState.InvalidCounts, + CalculationId = Guid.NewGuid(), + AgeMs = 1234, + }; + HealthVerb.CacheLookupResult result = HealthVerb.ParseCachedResponse(new NamedPipeMessages.Message("NA", info.ToBody())); + Assert.AreEqual(HealthVerb.CacheLookupOutcome.NotAvailable, result.Outcome); + Assert.AreEqual(info.CalculationId, result.Info.CalculationId); + Assert.AreEqual(NamedPipeMessages.HydrationStatus.CacheState.InvalidCounts, result.Info.State); + Assert.IsNull(result.Counts); + } + + [TestCase] + public void CachedDisplayRecordsCountsWithoutFallback() + { + using (StringWriter output = new StringWriter()) + using (MockTracer tracer = new MockTracer()) + { + CachedHealthVerb verb = new CachedHealthVerb { Output = output }; + EventMetadata metadata = new EventMetadata(); + verb.OutputHydrationPercent(null, tracer, metadata, Guid.NewGuid()); + Assert.AreEqual("Cache", metadata["ResultSource"]); + Assert.AreEqual("Percentage", metadata["DisplayOutcome"]); + Assert.AreEqual(HealthVerb.HealthCommandOutcome.Success, metadata["Outcome"]); + Assert.IsNull(metadata["CalculationOutcome"]); + EventMetadata cache = (EventMetadata)metadata["Cache"]; + Assert.AreEqual(HealthVerb.CacheLookupOutcome.Success, cache["Outcome"]); + Assert.AreEqual(100, ((EventMetadata)cache["Counts"])["TotalFileCount"]); + Assert.That(output.ToString(), Does.Contain("4% of files and 12% of folders hydrated.")); + } + } + + [TestCase("NotComputed", 0)] + [TestCase("Available", 1)] + [TestCase("ProviderUnavailable", 2)] + [TestCase("FeatureDisabled", 3)] + [TestCase("CircuitBreakerDisabled", 4)] + [TestCase("InvalidCounts", 5)] + [TestCase("IncompleteData", 6)] + [TestCase("Cancelled", 7)] + [TestCase("Failed", 8)] + public void CacheStateIntegersAreWireContracts(string state, int value) + { + Assert.AreEqual(value, (int)Enum.Parse(state)); + Assert.AreEqual("D1," + value + ",-,-1,0,0", + new NamedPipeMessages.HydrationStatus.CacheInfo { State = (NamedPipeMessages.HydrationStatus.CacheState)value }.ToBody()); + Assert.IsTrue(NamedPipeMessages.HydrationStatus.CacheInfo.TryParse("D1," + value + ",-,-1,0,0", out NamedPipeMessages.HydrationStatus.CacheInfo parsed)); + Assert.AreEqual(-1, parsed.AgeMs); + } + + [TestCase("NA", null, "NotAvailable", "Absent")] + [TestCase("NA", "private-path", "NotAvailable", "Unrecognized")] + [TestCase("S", "1,2,3,4,100,50,D2,private", "Success", "Unrecognized")] + [TestCase("unknown", "private", "UnexpectedResponse", "Absent")] + [TestCase("S", "1,2,3,4,100,50,D1,999,-,0,0,0", "Success", "Unrecognized")] + [TestCase("S", "1,2,3,4,100,50,D1,1,private,-2,0,0", "Success", "Unrecognized")] + public void UnknownResponsesPreserveSafeProvenance(string header, string body, string outcome, string diagnostics) + { + HealthVerb.CacheLookupResult result = HealthVerb.ParseCachedResponse(new NamedPipeMessages.Message(header, body)); + Assert.AreEqual(outcome, result.Outcome.ToString()); + Assert.AreEqual(diagnostics, result.DiagnosticsStatus.ToString()); + Assert.That(EventMetadataConverter.SerializeToString(result.GetMetadata()), Does.Not.Contain("private")); + } + + [TestCase] + public void AdversarialResponsesCannotCopyRawTextIntoTelemetry() + { + string[] bodies = + { + null, + string.Empty, + ",,,,,", + "1,2,3,4,100,50,D1,99,-,0,0,0", + "1,2,3,4,100,50,D1,1,private,0,0,0", + "1,2,3,4,100,50,D1,1,{01234567-89ab-cdef-0123-456789abcdef},0,0,0", + "1,2,3,4,100,50,D1,1,-,9223372036854775808,0,0", + "2147483648,0,0,0,0,0", + "2147483647,0,2147483647,0,1,1", + new string(',', 1024 * 1024), + }; + foreach (string body in bodies) + { + HealthVerb.CacheLookupResult result = HealthVerb.ParseCachedResponse(new NamedPipeMessages.Message("S", body)); + string payload = EventMetadataConverter.SerializeToString(result.GetMetadata()); + Assert.That(payload, Does.Not.Contain("private")); + Assert.That(payload.Length, Is.LessThan(2048)); + Assert.IsNull(result.Info); + Assert.IsTrue(result.Counts.Values.All(value => value == null || value is int)); + } + } + + [TestCase(true)] + [TestCase(false)] + public void CacheHitKeepsCommandOutcomeSeparateFromCompleteness(bool complete) + { + using (StringWriter output = new StringWriter()) + using (MockTracer tracer = new MockTracer()) + { + NamedPipeMessages.HydrationStatus.CacheInfo info = new NamedPipeMessages.HydrationStatus.CacheInfo + { + CountsComplete = complete, + State = complete ? NamedPipeMessages.HydrationStatus.CacheState.Available : NamedPipeMessages.HydrationStatus.CacheState.IncompleteData, + CalculationId = Guid.NewGuid(), + }; + WorkerHealthVerb verb = new WorkerHealthVerb { Output = output }; + verb.Pipe.Response = new NamedPipeMessages.Message("S", "1,2,3,4,100,50," + info.ToBody()); + EventMetadata metadata = new EventMetadata(); + verb.OutputHydrationPercent(null, tracer, metadata, Guid.NewGuid()); + Assert.AreEqual(HealthVerb.HealthCommandOutcome.Success, metadata["Outcome"]); + Assert.AreEqual(complete ? HydrationSummaryOutcome.Success : HydrationSummaryOutcome.IncompleteData, metadata["CalculationOutcome"]); + Assert.AreEqual(info.CalculationId.Value.ToString("N"), metadata["CalculationId"]); + Assert.AreEqual("Cache", metadata["ResultSource"]); + Assert.IsTrue(verb.Pipe.Disposed); + } + } + + [TestCase("ConnectTimeout", "Connect")] + [TestCase("ConnectFailed", "Connect")] + [TestCase("SendFailed", "Send")] + [TestCase("ReadFailed", "Read")] + [Category(CategoryConstants.ExceptionExpected)] + public void RealWorkerRecordsTransportFailureAndPhase(string failure, string phase) + { + WorkerHealthVerb verb = new WorkerHealthVerb(); + verb.Pipe.ConnectError = failure == "ConnectTimeout" ? new TimeoutException("private") + : failure == "ConnectFailed" ? new IOException("private") : null; + verb.Pipe.SendError = failure == "SendFailed" ? new IOException("private") : null; + verb.Pipe.ReadError = failure == "ReadFailed" ? new IOException("private") : null; + HealthVerb.CacheLookupResult result = verb.TryGetCachedHydrationStatus(null); + Assert.AreEqual(failure.EndsWith("Failed") && phase != "Connect" ? "Failed" : failure, result.Outcome.ToString()); + Assert.AreEqual(phase, result.Phase.ToString()); + Assert.AreEqual(500, verb.Pipe.ConnectTimeoutMs); + Assert.IsTrue(verb.Pipe.Disposed); + Assert.That(EventMetadataConverter.SerializeToString(result.GetMetadata()), Does.Not.Contain("private")); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void RealPipeConnectionReturnsItsTimeoutCause() + { + using (NamedPipeClient client = new NamedPipeClient("GVFS.UnitTests.Missing." + Guid.NewGuid().ToString("N"))) + { + Assert.IsFalse(client.Connect(25, out Exception error)); + Assert.IsInstanceOf(error); + } + } + + [TestCase] + public void LateWorkerDoesNotMutateTimeoutMetadata() + { + using (ManualResetEventSlim release = new ManualResetEventSlim()) + { + WorkerHealthVerb verb = new WorkerHealthVerb(); + verb.Pipe.ReadResponseCallback = () => + { + if (!release.Wait(TimeSpan.FromSeconds(10))) + { + throw new TimeoutException("Test did not release the pipe worker."); + } + + return new NamedPipeMessages.Message("S", "1,2,3,4,100,50"); + }; + try + { + HealthVerb.CacheLookupResult result = verb.TryGetCachedHydrationStatus(null); + Assert.AreEqual(HealthVerb.CacheLookupOutcome.Timeout, result.Outcome); + Assert.That(result.DurationMs, Is.GreaterThanOrEqualTo(900)); + string before = EventMetadataConverter.SerializeToString(result.GetMetadata()); + release.Set(); + Assert.IsTrue(SpinWait.SpinUntil(() => verb.Pipe.Disposed, TimeSpan.FromSeconds(5))); + Assert.AreEqual(before, EventMetadataConverter.SerializeToString(result.GetMetadata())); + } + finally + { + release.Set(); + SpinWait.SpinUntil(() => verb.Pipe.Disposed, TimeSpan.FromSeconds(5)); + } + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalFailureRetainsIdentityWithoutLeakingExceptionText() + { + using (JsonTracer tracer = new JsonTracer("test", "health", disableTelemetry: true)) + { + MetadataListener telemetry = new MetadataListener(Keywords.Telemetry); + MetadataListener local = new MetadataListener(Keywords.Any); + tracer.AddEventListener(telemetry); + tracer.AddEventListener(local); + ThrowingHealthVerb verb = new ThrowingHealthVerb(); + Assert.Throws(() => verb.ExecuteWithCompletion(null, tracer, Guid.NewGuid())); + string completion = telemetry.Events.Single(e => e.EventName == "health").Payload; + Assert.That(completion, Does.Contain("\"Outcome\":\"Failed\"")); + Assert.That(completion, Does.Contain("\"ExceptionType\":\"System.IO.IOException\"")); + Assert.That(completion, Does.Not.Contain("private")); + Assert.That(local.Events.Single(e => e.EventName == "Warning").Payload, Does.Contain("private")); + } + } + + private sealed class WorkerHealthVerb : HealthVerb + { + public MockNamedPipeClient Pipe { get; } = new MockNamedPipeClient(); + + internal override NamedPipeClient CreateHydrationPipeClient(GVFSEnlistment enlistment) + { + return this.Pipe; + } + } + + private sealed class ThrowingHealthVerb : HealthVerb + { + internal override void ExecuteWithTracer(GVFSEnlistment enlistment, ITracer tracer, EventMetadata metadata, Guid commandId) + { + throw new IOException("mock:\\private\\details"); + } + } + + private sealed class MetadataListener : EventListener + { + public MetadataListener(Keywords keywords) : base(EventLevel.Verbose, keywords, null) + { + } + + public List Events { get; } = new List(); + + protected override void RecordMessageInternal(TraceEventMessage message) + { + this.Events.Add(message); + } + } + + [TestCase] + public void DiagnosticArithmeticDoesNotOverflowOrHideMultipleFailures() + { + HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics + { + PlaceholderFileCount = int.MaxValue, + ModifiedFileCount = int.MaxValue, + TotalFileCount = 1, + PlaceholderFolderCount = 2, + ModifiedFolderCount = 3, + TotalFolderCount = 1, + }; + HydrationValidationFailure failures = diagnostics.GetValidationFailures(); + Assert.IsTrue(failures.HasFlag(HydrationValidationFailure.FileSumOverflow)); + Assert.IsTrue(failures.HasFlag(HydrationValidationFailure.HydratedFilesExceedTotal)); + Assert.IsTrue(failures.HasFlag(HydrationValidationFailure.HydratedFoldersExceedTotal)); + Assert.AreEqual(4294967294L, diagnostics.GetMetadata()["HydratedFileCount"]); + } + + [TestCase] + public void DiskDiagnosticsObserveOperationsWithoutChangingReplaySemantics() + { + using (Stream stream = new MemoryStream(System.Text.Encoding.UTF8.GetBytes("A a\nD a\nA b/\ninvalid\n"))) + using (StreamReader streamReader = new StreamReader(stream)) + { + HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics(); + string[] lines = new EnlistmentPathData().ReadModifiedPathDatabaseLines(streamReader, diagnostics).ToArray(); + Assert.AreEqual(new[] { "a", "D a", "b/", "invalid" }, lines); + Assert.AreEqual(2, diagnostics.ModifiedPathsAddRecords); + Assert.AreEqual(1, diagnostics.ModifiedPathsDeleteRecords); + Assert.AreEqual(1, diagnostics.ModifiedPathsOtherRecords); + } + } + + private sealed class CachedHealthVerb : HealthVerb + { + internal override CacheLookupResult TryGetCachedHydrationStatus(GVFSEnlistment enlistment) + { + return ParseCachedResponse(new NamedPipeMessages.Message("S", "1,2,3,4,100,50")); + } + + internal override EnlistmentHydrationSummary CreateHydrationSummary(GVFSEnlistment enlistment, ITracer tracer, HydrationSummaryDiagnostics diagnostics) + { + Assert.Fail("A cached result must not calculate a fallback."); + return null; + } + } + } +} diff --git a/GVFS/GVFS.UnitTests/Mock/Common/MockNamedPipeClient.cs b/GVFS/GVFS.UnitTests/Mock/Common/MockNamedPipeClient.cs new file mode 100644 index 0000000000..dd2fad6410 --- /dev/null +++ b/GVFS/GVFS.UnitTests/Mock/Common/MockNamedPipeClient.cs @@ -0,0 +1,50 @@ +using GVFS.Common.NamedPipes; +using System; + +namespace GVFS.UnitTests.Mock.Common +{ + public class MockNamedPipeClient : NamedPipeClient + { + public MockNamedPipeClient() : base("mock-pipe") + { + } + + public Exception ConnectError { get; set; } + public Exception SendError { get; set; } + public Exception ReadError { get; set; } + public Func ReadResponseCallback { get; set; } + public NamedPipeMessages.Message Response { get; set; } + public bool Disposed { get; private set; } + public int ConnectTimeoutMs { get; private set; } + + public override bool Connect(int timeoutMilliseconds, out Exception error) + { + this.ConnectTimeoutMs = timeoutMilliseconds; + error = this.ConnectError; + return error == null; + } + + public override void SendRequest(NamedPipeMessages.Message message) + { + if (this.SendError != null) + { + throw this.SendError; + } + } + + public override NamedPipeMessages.Message ReadResponse() + { + if (this.ReadError != null) + { + throw this.ReadError; + } + + return this.ReadResponseCallback == null ? this.Response : this.ReadResponseCallback(); + } + + public override void Dispose() + { + this.Disposed = true; + } + } +} diff --git a/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs b/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs index f1deffe98f..3c9ced2ac8 100644 --- a/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs +++ b/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs @@ -4,12 +4,119 @@ using GVFS.Common.Tracing; using GVFS.Tests.Should; using NUnit.Framework; +using GVFS.Common; +using System; +using System.IO; +using System.IO.Pipes; +using System.Threading; +using System.Threading.Tasks; +using GVFS.CommandLine; +using GVFS.Common.FileSystem; +using GVFS.Common.NamedPipes; +using GVFS.UnitTests.Mock.Common; +using GVFS.UnitTests.Category; namespace GVFS.UnitTests.Tracing { [TestFixture] public class TelemetryDaemonEventListenerTests { + [TestCase(false)] + [TestCase(true)] + [Category(CategoryConstants.ExceptionExpected)] + public async Task HydrationMetadataReachesTheCollectorWithNullsAndNestedCounts(bool cacheHit) + { + string pipeName = "GVFS.UnitTests.Hydration." + Guid.NewGuid().ToString("N"); + using (CancellationTokenSource deadline = new CancellationTokenSource(TimeSpan.FromSeconds(10))) + using (NamedPipeServerStream server = new NamedPipeServerStream(pipeName, PipeDirection.In, 1, PipeTransmissionMode.Byte, PipeOptions.Asynchronous)) + { + Task received = ReadTelemetryAsync(server, deadline.Token); + using (JsonTracer tracer = new JsonTracer("test", "health", disableTelemetry: true)) + using (StringWriter output = new StringWriter()) + { + tracer.AddEventListener(new TelemetryDaemonEventListener("test", "test-enlistment", "test-mount", pipeName, eventSink: null)); + CollectorHealthVerb verb = new CollectorHealthVerb { StatusOnly = true, CacheHit = cacheHit, Output = output }; + verb.ExecuteWithCompletion(null, tracer, Guid.NewGuid()); + } + + string[] lines = (await received).Split('\n', StringSplitOptions.RemoveEmptyEntries); + Assert.AreEqual(cacheHit ? 1 : 2, lines.Length); + TelemetryDaemonEventListener.PipeMessage health = TelemetryDaemonEventListener.PipeMessage.FromJson(lines.Last()); + Assert.AreEqual("health", health.EventName); + Assert.AreEqual("test-enlistment", health.Payload.EnlistmentId); + using (JsonDocument json = JsonDocument.Parse(health.Payload.Json)) + { + JsonElement root = json.RootElement; + Assert.AreEqual(cacheHit ? "Success" : "Failed", root.GetProperty("Outcome").GetString()); + if (cacheHit) + { + Assert.AreEqual(0, root.GetProperty("Cache").GetProperty("Counts").GetProperty("ModifiedFileCount").GetInt32()); + Assert.IsFalse(root.TryGetProperty("Summary", out _)); + } + else + { + JsonElement summary = root.GetProperty("Summary"); + Assert.AreEqual(100, summary.GetProperty("TotalFileCount").GetInt32()); + Assert.AreEqual(JsonValueKind.Null, summary.GetProperty("ModifiedFileCount").ValueKind); + Assert.AreEqual(JsonValueKind.Null, summary.GetProperty("TotalFolderCount").ValueKind); + Assert.AreEqual("Failed", summary.GetProperty("Outcome").GetString()); + TelemetryDaemonEventListener.PipeMessage duration = TelemetryDaemonEventListener.PipeMessage.FromJson(lines[0]); + Assert.AreEqual("HydrationSummaryDuration", duration.EventName); + using (JsonDocument calculation = JsonDocument.Parse(duration.Payload.Json)) + { + Assert.AreEqual(summary.GetRawText(), calculation.RootElement.GetRawText()); + Assert.AreEqual(root.GetProperty("CommandId").GetString(), summary.GetProperty("CommandId").GetString()); + } + } + } + + Assert.That(string.Join("\n", lines), Does.Not.Contain("private")); + } + } + + private sealed class CollectorHealthVerb : HealthVerb + { + public bool CacheHit { get; set; } + + internal override CacheLookupResult TryGetCachedHydrationStatus(GVFSEnlistment enlistment) + { + return ParseCachedResponse(this.CacheHit + ? new NamedPipeMessages.Message("S", "0,0,0,0,100,10") + : new NamedPipeMessages.Message("NA", null)); + } + + internal override EnlistmentHydrationSummary CreateHydrationSummary(GVFSEnlistment enlistment, ITracer tracer, HydrationSummaryDiagnostics diagnostics) + { + return EnlistmentHydrationSummary.CreateSummary(new MockGVFSEnlistment(), new HeaderFileSystem(), tracer, + () => 10, new FailingPlaceholderPaths(), diagnostics: diagnostics); + } + } + + private sealed class HeaderFileSystem : PhysicalFileSystem + { + public override Stream OpenFileStream(string path, FileMode fileMode, FileAccess fileAccess, FileShare shareMode, FileOptions options, bool flushesToDisk) + { + return new MemoryStream(new byte[] { 68, 73, 82, 67, 0, 0, 0, 4, 0, 0, 0, 100 }); + } + } + + private sealed class FailingPlaceholderPaths : EnlistmentPathData + { + public override void LoadPlaceholdersFromDatabase(GVFSEnlistment enlistment, HydrationSummaryDiagnostics diagnostics = null) + { + throw new IOException("mock:\\private\\database"); + } + } + + private static async Task ReadTelemetryAsync(NamedPipeServerStream server, CancellationToken cancellationToken) + { + await server.WaitForConnectionAsync(cancellationToken).ConfigureAwait(false); + using (StreamReader reader = new StreamReader(server)) + { + return await reader.ReadToEndAsync(cancellationToken).ConfigureAwait(false); + } + } + [TestCase] public void TraceMessageDataIsCorrectFormat() { diff --git a/GVFS/GVFS.Virtualization/FileSystemCallbacks.cs b/GVFS/GVFS.Virtualization/FileSystemCallbacks.cs index c9fc1cd2a1..68358e8dd7 100644 --- a/GVFS/GVFS.Virtualization/FileSystemCallbacks.cs +++ b/GVFS/GVFS.Virtualization/FileSystemCallbacks.cs @@ -584,9 +584,9 @@ public void InvalidateGitStatusCache() } } - public EnlistmentHydrationSummary GetCachedHydrationSummary() + public EnlistmentHydrationSummary GetCachedHydrationSummary(out NamedPipeMessages.HydrationStatus.CacheInfo info) { - return this.gitStatusCache.GetCachedHydrationSummary(); + return this.gitStatusCache.GetCachedHydrationSummary(out info); } public int GetProjectedFolderCount() diff --git a/GVFS/GVFS/CommandLine/HealthVerb.cs b/GVFS/GVFS/CommandLine/HealthVerb.cs index 8bb453ac9c..a6128dd8e3 100644 --- a/GVFS/GVFS/CommandLine/HealthVerb.cs +++ b/GVFS/GVFS/CommandLine/HealthVerb.cs @@ -4,8 +4,10 @@ using GVFS.Common.Tracing; using System; using System.Collections.Generic; +using System.Diagnostics; using System.IO; using System.Linq; +using System.Threading; using System.Threading.Tasks; namespace GVFS.CommandLine @@ -68,106 +70,283 @@ protected override void Execute(GVFSEnlistment enlistment) EventLevel.Informational, Keywords.Any); - if (this.StatusOnly) + Guid commandId = Guid.NewGuid(); + this.ExecuteWithCompletion(enlistment, tracer, commandId); + } + } + + internal void ExecuteWithCompletion(GVFSEnlistment enlistment, ITracer tracer, Guid commandId) + { + EventMetadata metadata = new EventMetadata + { + ["SchemaVersion"] = 1, + ["CommandId"] = commandId.ToString("N"), + ["Mode"] = this.StatusOnly ? "Status" : "Detailed", + ["Outcome"] = HealthCommandOutcome.Failed, + }; + try + { + this.ExecuteWithTracer(enlistment, tracer, metadata, commandId); + } + catch (Exception e) + { + metadata["Outcome"] = HealthCommandOutcome.Failed; + metadata["ExceptionType"] = e.GetType().FullName; + metadata["ExceptionHResult"] = e.HResult; + tracer.RelatedWarning(new EventMetadata { ["Exception"] = e.ToString() }, "Health command failed.", Keywords.None); + throw; + } + finally + { + tracer.Stop(metadata); + } + } + + internal virtual void ExecuteWithTracer(GVFSEnlistment enlistment, ITracer tracer, EventMetadata metadata, Guid commandId) + { + if (this.StatusOnly) + { + this.OutputHydrationPercent(enlistment, tracer, metadata, commandId); + return; + } + + // Now default to the current working directory when running the verb without a specified path + if (string.IsNullOrEmpty(this.Directory) || this.Directory.Equals(".")) + { + if (Environment.CurrentDirectory.StartsWith(enlistment.WorkingDirectoryRoot, GVFSPlatform.Instance.Constants.PathComparison)) { - this.OutputHydrationPercent(enlistment, tracer); - return; + this.Directory = Environment.CurrentDirectory.Substring(enlistment.WorkingDirectoryRoot.Length); } - - // Now default to the current working directory when running the verb without a specified path - if (string.IsNullOrEmpty(this.Directory) || this.Directory.Equals(".")) + else { - if (Environment.CurrentDirectory.StartsWith(enlistment.WorkingDirectoryRoot, GVFSPlatform.Instance.Constants.PathComparison)) - { - this.Directory = Environment.CurrentDirectory.Substring(enlistment.WorkingDirectoryRoot.Length); - } - else - { - // If the path is not under the source root, set the directory to empty - this.Directory = string.Empty; - } + // If the path is not under the source root, set the directory to empty + this.Directory = string.Empty; } + } - this.Output.WriteLine("\nGathering repository data..."); + this.Output.WriteLine("\nGathering repository data..."); - this.Directory = this.Directory.Replace(GVFSPlatform.GVFSPlatformConstants.PathSeparator, GVFSConstants.GitPathSeparator); + this.Directory = this.Directory.Replace(GVFSPlatform.GVFSPlatformConstants.PathSeparator, GVFSConstants.GitPathSeparator); - EnlistmentPathData pathData = new EnlistmentPathData(); + EnlistmentPathData pathData = new EnlistmentPathData(); - pathData.LoadPlaceholdersFromDatabase(enlistment); - pathData.LoadModifiedPaths(enlistment, tracer); - pathData.LoadPathsFromGitIndex(enlistment); + pathData.LoadPlaceholdersFromDatabase(enlistment); + pathData.LoadModifiedPaths(enlistment, tracer); + pathData.LoadPathsFromGitIndex(enlistment); - pathData.NormalizeAllPaths(); + pathData.NormalizeAllPaths(); - EnlistmentHealthCalculator enlistmentHealthCalculator = new EnlistmentHealthCalculator(pathData); - EnlistmentHealthData enlistmentHealthData = enlistmentHealthCalculator.CalculateStatistics(this.Directory); + EnlistmentHealthCalculator enlistmentHealthCalculator = new EnlistmentHealthCalculator(pathData); + EnlistmentHealthData enlistmentHealthData = enlistmentHealthCalculator.CalculateStatistics(this.Directory); - this.PrintOutput(enlistmentHealthData); - } + this.PrintOutput(enlistmentHealthData); + metadata["Outcome"] = HealthCommandOutcome.Success; } - private void OutputHydrationPercent(GVFSEnlistment enlistment, ITracer tracer) + internal void OutputHydrationPercent(GVFSEnlistment enlistment, ITracer tracer, EventMetadata metadata, Guid commandId) { - // Try cached summary from mount process first (fast path) - string cachedMessage = this.TryGetCachedHydrationMessage(enlistment); - if (cachedMessage != null) + CacheLookupResult cache = this.TryGetCachedHydrationStatus(enlistment); + metadata["Cache"] = cache.GetMetadata(); + if (cache.Exception != null) + { + tracer.RelatedWarning(new EventMetadata { ["Exception"] = cache.Exception.ToString() }, "Hydration cache lookup failed.", Keywords.None); + } + + if (cache.Response != null && cache.Outcome == CacheLookupOutcome.Success) { - this.Output.WriteLine(cachedMessage); + metadata["ResultSource"] = "Cache"; + metadata["DisplayOutcome"] = "Percentage"; + metadata["Outcome"] = HealthCommandOutcome.Success; + metadata["CalculationOutcome"] = cache.Info == null ? null + : cache.Info.CountsComplete ? HydrationSummaryOutcome.Success : HydrationSummaryOutcome.IncompleteData; + metadata["CalculationId"] = cache.Info?.CalculationId?.ToString("N"); + this.Output.WriteLine(cache.Response.ToDisplayMessage()); return; } - // Fall back to in-proc computation with index-based folder count - Func folderCountProvider = () => - GVFS.Virtualization.Projection.GitIndexProjection.CountIndexFolders(tracer, enlistment.GitIndexPath); - EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( - enlistment, this.FileSystem, tracer, folderCountProvider); + metadata["ResultSource"] = "Fallback"; + HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics + { + CommandId = commandId, + Caller = HydrationSummaryCaller.HealthFallback, + FolderCountSource = HydrationFolderCountSource.IndexParser, + }; + EnlistmentHydrationSummary summary = this.CreateHydrationSummary(enlistment, tracer, diagnostics); + metadata["Summary"] = diagnostics.GetMetadata(); + metadata["CalculationId"] = diagnostics.CalculationId.ToString("N"); + metadata["Outcome"] = summary.IsValid ? HealthCommandOutcome.Success : HealthCommandOutcome.Failed; + metadata["CalculationOutcome"] = diagnostics.Outcome; + metadata["DisplayOutcome"] = summary.IsValid ? "Percentage" : "Error"; this.Output.WriteLine(summary.ToMessage()); } - /// - /// Try to get the cached hydration summary from the mount process via named pipe. - /// Returns null if unavailable (GVFS not mounted, no cached value, parse error, timeout). - /// - private string TryGetCachedHydrationMessage(GVFSEnlistment enlistment) + internal virtual EnlistmentHydrationSummary CreateHydrationSummary(GVFSEnlistment enlistment, ITracer tracer, HydrationSummaryDiagnostics diagnostics) + { + return EnlistmentHydrationSummary.CreateSummary(enlistment, this.FileSystem, tracer, + () => GVFS.Virtualization.Projection.GitIndexProjection.CountIndexFolders(tracer, enlistment.GitIndexPath), + diagnostics: diagnostics); + } + + internal virtual CacheLookupResult TryGetCachedHydrationStatus(GVFSEnlistment enlistment) { const int ConnectTimeoutMs = 500; const int TotalTimeoutMs = 1000; - - try + Stopwatch stopwatch = Stopwatch.StartNew(); + int phase = (int)CacheLookupPhase.Connect; + Task task = Task.Run(() => { - Task task = Task.Run(() => + try { - using (NamedPipeClient pipeClient = new NamedPipeClient(enlistment.NamedPipeName)) + using (NamedPipeClient pipeClient = this.CreateHydrationPipeClient(enlistment)) { - if (!pipeClient.Connect(timeoutMilliseconds: ConnectTimeoutMs)) + if (!pipeClient.Connect(ConnectTimeoutMs, out Exception error)) { - return null; + return new CacheLookupResult + { + Outcome = error is TimeoutException ? CacheLookupOutcome.ConnectTimeout : CacheLookupOutcome.ConnectFailed, + Phase = CacheLookupPhase.Connect, + Exception = error, + }; } + Volatile.Write(ref phase, (int)CacheLookupPhase.Send); pipeClient.SendRequest(new NamedPipeMessages.Message(NamedPipeMessages.HydrationStatus.Request, null)); + Volatile.Write(ref phase, (int)CacheLookupPhase.Read); NamedPipeMessages.Message response = pipeClient.ReadResponse(); - - if (response.Header != NamedPipeMessages.HydrationStatus.SuccessResult - || !NamedPipeMessages.HydrationStatus.Response.TryParse(response.Body, out NamedPipeMessages.HydrationStatus.Response status)) - { - return null; - } - - return status.ToDisplayMessage(); + Volatile.Write(ref phase, (int)CacheLookupPhase.Parse); + return ParseCachedResponse(response); } - }); - - if (task.Wait(TotalTimeoutMs) && task.Status == TaskStatus.RanToCompletion) + } + catch (Exception ex) { - return task.Result; + return new CacheLookupResult { Outcome = CacheLookupOutcome.Failed, Phase = (CacheLookupPhase)Volatile.Read(ref phase), Exception = ex }; } + }); - return null; + CacheLookupResult result; + if (task.Wait(TotalTimeoutMs)) + { + result = task.Result; } - catch (Exception) + else { - return null; + // The worker owns the pipe and never writes to the caller's tracer or metadata after a timeout. + result = new CacheLookupResult { Outcome = CacheLookupOutcome.Timeout, Phase = (CacheLookupPhase)Volatile.Read(ref phase) }; + } + + result.DurationMs = stopwatch.ElapsedMilliseconds; + return result; + } + + internal virtual NamedPipeClient CreateHydrationPipeClient(GVFSEnlistment enlistment) + { + return new NamedPipeClient(enlistment.NamedPipeName); + } + + internal enum HealthCommandOutcome + { + Success, + Failed, + } + + internal static CacheLookupResult ParseCachedResponse(NamedPipeMessages.Message message) + { + CacheLookupResult result = new CacheLookupResult { Phase = CacheLookupPhase.Parse }; + if (message.Header == NamedPipeMessages.HydrationStatus.NotAvailableResult) + { + result.Outcome = CacheLookupOutcome.NotAvailable; + NamedPipeMessages.HydrationStatus.CacheInfo.TryParse(message.Body, out NamedPipeMessages.HydrationStatus.CacheInfo info); + result.Info = info; + result.DiagnosticsStatus = info != null ? CacheDiagnosticsStatus.Parsed + : string.IsNullOrEmpty(message.Body) ? CacheDiagnosticsStatus.Absent : CacheDiagnosticsStatus.Unrecognized; + return result; + } + + if (message.Header != NamedPipeMessages.HydrationStatus.SuccessResult) + { + result.Outcome = CacheLookupOutcome.UnexpectedResponse; + return result; + } + + result.Counts = new EventMetadata(); + string[] parts = message.Body?.Split(',') ?? Array.Empty(); + string[] names = { "PlaceholderFileCount", "PlaceholderFolderCount", "ModifiedFileCount", "ModifiedFolderCount", "TotalFileCount", "TotalFolderCount" }; + for (int i = 0; i < names.Length; i++) + { + result.Counts[names[i]] = i < parts.Length && int.TryParse(parts[i], out int count) ? count : null; + } + + bool valid = NamedPipeMessages.HydrationStatus.Response.TryParse(message.Body, out NamedPipeMessages.HydrationStatus.Response response, out NamedPipeMessages.HydrationStatus.ParseOutcome outcome); + result.Response = response; + result.ParseOutcome = outcome; + result.Outcome = valid ? CacheLookupOutcome.Success + : outcome == NamedPipeMessages.HydrationStatus.ParseOutcome.InvalidCounts ? CacheLookupOutcome.InvalidCounts : CacheLookupOutcome.MalformedResponse; + NamedPipeMessages.HydrationStatus.CacheInfo.TryParse(message.Body, out NamedPipeMessages.HydrationStatus.CacheInfo cacheInfo, hasCounts: true); + result.Info = cacheInfo; + result.DiagnosticsStatus = cacheInfo != null ? CacheDiagnosticsStatus.Parsed + : parts.Length <= 6 ? CacheDiagnosticsStatus.Absent : CacheDiagnosticsStatus.Unrecognized; + return result; + } + + internal enum CacheDiagnosticsStatus + { + Absent, + Parsed, + Unrecognized, + } + + internal enum CacheLookupOutcome + { + Success, + NotAvailable, + ConnectTimeout, + ConnectFailed, + Timeout, + UnexpectedResponse, + MalformedResponse, + InvalidCounts, + Failed, + } + + internal enum CacheLookupPhase + { + Connect, + Send, + Read, + Parse, + } + + internal sealed class CacheLookupResult + { + public CacheLookupOutcome Outcome { get; set; } + public CacheLookupPhase Phase { get; set; } + public long DurationMs { get; set; } + public Exception Exception { get; set; } + public NamedPipeMessages.HydrationStatus.Response Response { get; set; } + public NamedPipeMessages.HydrationStatus.ParseOutcome? ParseOutcome { get; set; } + public NamedPipeMessages.HydrationStatus.CacheInfo Info { get; set; } + public EventMetadata Counts { get; set; } + public CacheDiagnosticsStatus DiagnosticsStatus { get; set; } + + public EventMetadata GetMetadata() + { + return new EventMetadata + { + [nameof(this.Outcome)] = this.Outcome, + [nameof(this.Phase)] = this.Phase, + [nameof(this.DurationMs)] = this.DurationMs, + ["ExceptionType"] = this.Exception?.GetType().FullName, + ["ExceptionHResult"] = this.Exception?.HResult, + [nameof(this.ParseOutcome)] = this.ParseOutcome, + [nameof(this.Counts)] = this.Counts, + ["DiagnosticsAvailable"] = this.Info != null, + [nameof(this.DiagnosticsStatus)] = this.DiagnosticsStatus, + ["State"] = this.Info?.State, + ["CalculationId"] = this.Info?.CalculationId?.ToString("N"), + ["AgeMs"] = this.Info?.AgeMs, + ["Invalidated"] = this.Info?.Invalidated, + ["CountsComplete"] = this.Info?.CountsComplete, + }; } } diff --git a/docs/hydration-status-diagnostics.md b/docs/hydration-status-diagnostics.md new file mode 100644 index 0000000000..4423e459b5 --- /dev/null +++ b/docs/hydration-status-diagnostics.md @@ -0,0 +1,115 @@ +# Hydration status diagnostics + +`gvfs health --status` first requests a cached hydration summary from the mount process. +If that request fails, the command calculates a summary locally. +The diagnostic fields describe both attempts without a repository path or a raw pipe response. + +## Calculation result + +`HydrationSummaryDuration` contains one terminal record for each calculation. +It retains the existing duration fields and adds `SchemaVersion: 1`. +It records success, invalid counts, incomplete data, cancellation, and exceptions. +Success and cancellation use the Informational level. +Invalid counts, incomplete data, and exceptions use the Warning level. + +The six count fields contain numbers or JSON null. +A null value means that the calculation did not obtain that count. +A collected zero remains zero. +Partial counts remain available, but their source state is not `Complete`. + +`IndexState`, `PlaceholderState`, `ModifiedPathsState`, and `FolderCountState` describe source completeness. +`CountsComplete` requires all four states to equal `Complete`. +`IsValid` records the existing display calculation. +`ValidationFailures` independently records missing counts, negative counts, overflow, and hydrated counts that exceed their totals. +Its arithmetic uses 64-bit sums. + +`Phase` identifies the last started phase, which can already be complete when cancellation occurs between phases. +`CancellationRequested` distinguishes caller-requested cancellation from other cancellation exceptions. +Neither cancellation type increments the circuit breaker. +Each duration includes failed work in that phase. +An unattempted phase has a null duration. +`TreeCountMs` retains its existing name and measures the folder-count provider. +`FolderCountSource` identifies `Projection`, `IndexParser`, or `Unknown`. + +The index fields record its observed length, version, signature validity, and header-read result. +An unavailable index total produces `IncompleteData`, not an arithmetic inconsistency. +They do not prove that all sources came from one atomic repository snapshot. +The placeholder fields distinguish partial, expanded, and possible-tombstone folders. + +The modified-path fields describe the pipe attempt and the disk fallback separately. +The disk fields count add, delete, and other records. +These fields describe the existing reader. +They do not change its replay semantics or the recursive meaning of modified-folder entries. + +## Command result and cache + +The `health` completion record distinguishes `Status` mode from `Detailed` mode. +Status mode records the cache outcome, fallback decision, displayed result, and calculation identity. +Command `Outcome` uses `Success` when the command displays its result, or `Failed` when it reports an error. +`CalculationOutcome` describes the calculation separately. +Legacy cache responses leave `CalculationOutcome` unknown. +The nested `Cache` object retains parseable counts even when response validation fails. +Legacy mount responses have no cache diagnostics. +Their absent fields remain unknown. + +`CommandId` identifies one health invocation. +`CalculationId` identifies one calculation and also travels with the cache response. +These fields appear explicitly in the JSON payload. +Activity identifiers in the local tracer are not sufficient for telemetry correlation. + +The hydration pipe keeps its `S` and `NA` response headers. +An `S` response starts with the existing six comma-separated counts. +An optional extension follows those counts: + +```text +D1,state,calculationId,ageMs,invalidated,countsComplete +``` + +An `NA` response can contain this extension without counts. +The state integers are fixed wire values: + +| State | Integer | +| --- | --- | +| NotComputed | 0 | +| Available | 1 | +| ProviderUnavailable | 2 | +| FeatureDisabled | 3 | +| CircuitBreakerDisabled | 4 | +| InvalidCounts | 5 | +| IncompleteData | 6 | +| Cancelled | 7 | +| Failed | 8 | + +The calculation identifier uses the GUID `N` format, or `-` when unavailable. +The age is nonnegative, or `-1` when unavailable. +The last two fields use `0` or `1`. +Older clients ignore the extension. +New clients accept responses without it. + +The mount publishes the summary and its diagnostic identity together. +Cache state describes the latest refresh or skip decision. +A skipped refresh can retain an earlier valid summary. +`Invalidated` compares the calculation's invalidation generation with the current generation. +It does not reject a cached summary or change the existing cache policy. +Heartbeat telemetry aggregates hydration requests and unavailable responses. +`HydrationStatus.CurrentCacheState` describes the cache at the heartbeat, not the state of earlier requests. + +## Limits and privacy + +The health cache lookup retains its 500 ms connection timeout and 1000 ms outer wait. +The hook retains its existing timeout and does not create a telemetry process or listener. +A timed-out health worker can finish later. +It owns its pipe and cannot write to the command's tracer or completion record. +The modified-path reader retains its existing connection and response-wait behavior. + +Telemetry contains exception types and HRESULT values, not arbitrary exception messages or stacks. +Local warnings retain full exception details. +The structured result fields are identical in local logs and telemetry. +Raw details appear only in local warnings. + +Telemetry delivery remains best-effort. +The listener can drop events when its queue is full or its collector is unavailable. +Process termination can also prevent a terminal record. +Mount telemetry cannot observe a hook connection failure that never reaches the mount. + +Diagnostic collection must preserve count sets, disk-log replay, percentages, cache acceptance, and circuit-breaker policy. diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index 8b91ed346a..ea8bb4a80d 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -1,6 +1,11 @@ Troubleshooting =============== +Hydration status +---------------- + +[Hydration status diagnostics](hydration-status-diagnostics.md) describes the structured results from `gvfs health --status` and the mount cache. + Deleting a VFS for Git repo ---------------------------