From da31d9879cedacdfa562f9bf3a790d77dbdb6ca0 Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Wed, 21 Oct 2026 16:13:35 -0700 Subject: [PATCH 1/4] Preserve hydration summary diagnostics across failures and cache fallback Record typed count availability, partial observations, validation failures, and phase outcomes. Correlate health commands with cached and fallback calculations through explicit payload identifiers and a compatible IPC extension. Keep count semantics and wait behavior unchanged. Add unit and functional tests for the diagnostic contract, serialization, and compatibility. Assisted-by: GPT-6.1 Sol Signed-off-by: Tyrie Vella --- GVFS/GVFS.Common/GitStatusCache.cs | 141 ++++++--- .../EnlistmentHydrationSummary.cs | 242 ++++++++-------- .../HealthCalculator/EnlistmentPathData.cs | 109 ++++++- .../HydrationSummaryDiagnostics.cs | 259 +++++++++++++++++ .../HydrationStatusNamedPipeMessages.cs | 86 +++++- .../GVFS.Common/NamedPipes/NamedPipeClient.cs | 12 +- .../Tracing/TelemetryDaemonEventListener.cs | 2 +- .../Tests/EnlistmentPerFixture/HealthTests.cs | 35 +++ .../Tools/GVFSFunctionalTestEnlistment.cs | 4 +- .../GVFS.FunctionalTests/Tools/GVFSProcess.cs | 7 +- GVFS/GVFS.Mount/InProcessMount.cs | 7 +- .../Common/EnlistmentHydrationSummaryTests.cs | 198 +++++++++++++ .../Common/GitStatusCacheTests.cs | 26 ++ .../Common/HydrationStatusDiagnosticsTests.cs | 163 +++++++++++ .../TelemetryDaemonEventListenerTests.cs | 53 ++++ .../FileSystemCallbacks.cs | 4 +- GVFS/GVFS/CommandLine/HealthVerb.cs | 273 ++++++++++++++---- docs/hydration-status-diagnostics.md | 93 ++++++ docs/troubleshooting.md | 5 + 19 files changed, 1487 insertions(+), 232 deletions(-) create mode 100644 GVFS/GVFS.Common/HealthCalculator/HydrationSummaryDiagnostics.cs create mode 100644 GVFS/GVFS.UnitTests/Common/HydrationStatusDiagnosticsTests.cs create mode 100644 docs/hydration-status-diagnostics.md diff --git a/GVFS/GVFS.Common/GitStatusCache.cs b/GVFS/GVFS.Common/GitStatusCache.cs index 870dce1c7c..d28544df4d 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.CacheState"] = this.hydrationCache.State; + wroteTelemetry = true; + } if (statusStatistics.BackgroundStatusScanCount > 0) { @@ -413,44 +454,57 @@ private void RebuildStatusCacheIfNeeded(bool ignoreBackoff) } } - private void UpdateHydrationSummary() + internal void UpdateHydrationSummary() { - if (this.projectedFolderCountProvider == null) - { - return; - } - - bool enabled = TEST_EnableHydrationSummaryOverride - ?? this.context.Repository.LibGit2RepoInvoker.GetConfigBoolOrDefault(GVFSConstants.GitConfig.ShowHydrationStatus, GVFSConstants.GitConfig.ShowHydrationStatusDefault); - if (!enabled) - { - return; - } - HydrationStatusCircuitBreaker circuitBreaker = new HydrationStatusCircuitBreaker( this.context.Enlistment.DotGVFSRoot, this.context.Tracer); - - if (circuitBreaker.IsDisabled()) - { - return; - } - try { + 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) + { + this.RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState.FeatureDisabled); + return; + } + + if (circuitBreaker.IsDisabled()) + { + this.RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState.CircuitBreakerDisabled); + return; + } + /* While not strictly part of git status, enlistment hydration summary is used * in "git status" pre-command hook, and can take several seconds to compute on very large repos. * 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); + EnlistmentHydrationSummary.CreateSummary(this.context.Enlistment, this.context.FileSystem, this.context.Tracer, this.projectedFolderCountProvider, this.shutdownTokenSource.Token, 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 +518,57 @@ 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); } } + 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..bfacee4885 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,172 @@ 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 = 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) when (cancellationToken.IsCancellationRequested) { - 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.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..a87d571413 100644 --- a/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs +++ b/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs @@ -49,7 +49,7 @@ 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(); @@ -61,7 +61,32 @@ public void LoadPlaceholdersFromDatabase(GVFSEnlistment enlistment) } this.PlaceholderFilePaths.AddRange(filePlaceholders.Select(placeholderData => placeholderData.Path)); - this.PlaceholderFolderPaths.AddRange(folderPlaceholders.Select(placeholderData => placeholderData.Path)); + if (diagnostics != null) + { + diagnostics.PartialFolderCount = 0; + diagnostics.ExpandedFolderCount = 0; + diagnostics.PossibleTombstoneFolderCount = 0; + } + + 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 +120,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; } @@ -109,16 +139,30 @@ public void LoadModifiedPaths(GVFSEnlistment enlistment, ITracer tracer) using (FileStream file = File.Open(filePath, FileMode.OpenOrCreate, FileAccess.Read, FileShare.Read)) using (StreamReader reader = new StreamReader(file)) { - AddModifiedPaths(ReadModifiedPathDatabaseLines(reader)); + AddModifiedPaths(ReadModifiedPathDatabaseLines(reader, diagnostics)); + if (diagnostics != null) + { + 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}"); } } - private IEnumerable ReadModifiedPathDatabaseLines(StreamReader r) + internal IEnumerable ReadModifiedPathDatabaseLines(StreamReader r, HydrationSummaryDiagnostics diagnostics = null) { while (!r.EndOfStream) { @@ -131,8 +175,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 +204,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)) { 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 +231,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 +246,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/HydrationSummaryDiagnostics.cs b/GVFS/GVFS.Common/HealthCalculator/HydrationSummaryDiagnostics.cs new file mode 100644 index 0000000000..cc2bde307c --- /dev/null +++ b/GVFS/GVFS.Common/HealthCalculator/HydrationSummaryDiagnostics.cs @@ -0,0 +1,259 @@ +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 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.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..d1cd16fb0a 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,6 +11,77 @@ public static class HydrationStatus public const string SuccessResult = "S"; public const string NotAvailableResult = "NA"; + public enum CacheState + { + NotComputed, + Available, + ProviderUnavailable, + FeatureDisabled, + CircuitBreakerDisabled, + InvalidCounts, + IncompleteData, + Cancelled, + Failed, + } + + 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 /// @@ -45,20 +117,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 +146,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 +157,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 +171,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..caa4cc137e 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 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; } 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..52254cfebe 100644 --- a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs +++ b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs @@ -8,6 +8,8 @@ using System.Globalization; using System.IO; using System.Text.RegularExpressions; +using System.Linq; +using System.Text.Json; namespace GVFS.FunctionalTests.Tests.EnlistmentPerFixture { @@ -137,6 +139,39 @@ public void FilterIntoDirectory() enlistmentHealthStatus: "Highly Hydrated"); } + [TestCase, Order(5)] + public void StatusRecordsTheDisplayedResultAndFallbackDiagnostics() + { + HashSet previousLogs = new HashSet(Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log")); + string output = this.Enlistment.Health(statusOnly: true); + string log = Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log").Single(path => !previousLogs.Contains(path)); + string[] lines = File.ReadAllLines(log); + string completion = lines.Single(line => line.Contains("health (Stop)")); + using (JsonDocument document = JsonDocument.Parse(completion.Substring(completion.IndexOf('{')))) + { + JsonElement root = document.RootElement; + 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().ShouldNotBeNull(); + string displayOutcome = root.GetProperty("DisplayOutcome").GetString(); + output.ShouldContain(displayOutcome == "Percentage" ? "% of files and " : "Error calculating hydration summary."); + if (root.GetProperty("ResultSource").GetString() == "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); + } + } + } + } + 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..772799c3d3 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,199 @@ 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"); + 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(2, summary.Diagnostics.PlaceholderFileCount); + Assert.IsNull(summary.Diagnostics.TotalFolderCount); + if (phase != HydrationSummaryPhase.Placeholders) + { + Assert.AreEqual(3, summary.Diagnostics.ModifiedFileCount); + } + + string payload = telemetry.Events.Single(e => e.EventName == "HydrationSummaryDuration").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.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.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 UnrelatedCancellationExceptionIsFailure() + { + this.AddIndex(100); + EnlistmentHydrationSummary summary = EnlistmentHydrationSummary.CreateSummary( + this.context.Enlistment, this.fileSystem, this.tracer, () => throw new OperationCanceledException(), new TestPathData()); + Assert.AreEqual(HydrationSummaryOutcome.Failed, summary.Diagnostics.Outcome); + Assert.IsNotNull(summary.Error); + } + + private void AddIndex(int count) + { + byte[] bytes = new byte[12]; + Encoding.ASCII.GetBytes("DIRC").CopyTo(bytes, 0); + 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 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; + 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/GitStatusCacheTests.cs b/GVFS/GVFS.UnitTests/Common/GitStatusCacheTests.cs index 59737a83f8..26f0567bc1 100644 --- a/GVFS/GVFS.UnitTests/Common/GitStatusCacheTests.cs +++ b/GVFS/GVFS.UnitTests/Common/GitStatusCacheTests.cs @@ -88,6 +88,32 @@ 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 CanInvalidateCleanCache() { diff --git a/GVFS/GVFS.UnitTests/Common/HydrationStatusDiagnosticsTests.cs b/GVFS/GVFS.UnitTests/Common/HydrationStatusDiagnosticsTests.cs new file mode 100644 index 0000000000..26c1cca53c --- /dev/null +++ b/GVFS/GVFS.UnitTests/Common/HydrationStatusDiagnosticsTests.cs @@ -0,0 +1,163 @@ +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; + +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.That(body, Does.StartWith("1,2,3,4,100,50,D1,")); + 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("LegacyCache", metadata["Outcome"]); + 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] + 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/Tracing/TelemetryDaemonEventListenerTests.cs b/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs index f1deffe98f..8d3030fd4b 100644 --- a/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs +++ b/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs @@ -4,12 +4,65 @@ 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; namespace GVFS.UnitTests.Tracing { [TestFixture] public class TelemetryDaemonEventListenerTests { + [TestCase] + public async Task HydrationMetadataReachesTheCollectorWithNullsAndNestedCounts() + { + 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); + HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics + { + TotalFileCount = 100, + ModifiedFileCount = 0, + Outcome = HydrationSummaryOutcome.Failed, + ExceptionType = typeof(IOException).FullName, + }; + using (JsonTracer tracer = new JsonTracer("test", "test", disableTelemetry: true)) + { + tracer.AddEventListener(new TelemetryDaemonEventListener("test", "test-enlistment", "test-mount", pipeName, eventSink: null)); + tracer.RelatedEvent(EventLevel.Warning, "HydrationSummaryDuration", + new EventMetadata { ["Summary"] = diagnostics.GetMetadata() }, Keywords.Telemetry); + } + + string line = (await received).Split('\n')[0]; + TelemetryDaemonEventListener.PipeMessage envelope = TelemetryDaemonEventListener.PipeMessage.FromJson(line); + Assert.AreEqual("HydrationSummaryDuration", envelope.EventName); + Assert.AreEqual("test-enlistment", envelope.Payload.EnlistmentId); + using (JsonDocument json = JsonDocument.Parse(envelope.Payload.Json)) + { + JsonElement summary = json.RootElement.GetProperty("Summary"); + Assert.AreEqual(100, summary.GetProperty("TotalFileCount").GetInt32()); + Assert.AreEqual(0, summary.GetProperty("ModifiedFileCount").GetInt32()); + Assert.AreEqual(JsonValueKind.Null, summary.GetProperty("TotalFolderCount").ValueKind); + Assert.AreEqual("Failed", summary.GetProperty("Outcome").GetString()); + Assert.AreEqual(diagnostics.CalculationId.ToString("N"), summary.GetProperty("CalculationId").GetString()); + } + } + } + + 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..17b595c904 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,257 @@ protected override void Execute(GVFSEnlistment enlistment) EventLevel.Informational, Keywords.Any); - if (this.StatusOnly) + Guid commandId = Guid.NewGuid(); + EventMetadata metadata = new EventMetadata { - this.OutputHydrationPercent(enlistment, tracer); - return; + ["SchemaVersion"] = 1, + ["CommandId"] = commandId.ToString("N"), + ["Mode"] = this.StatusOnly ? "Status" : "Detailed", + ["Outcome"] = "Failed", + }; + try + { + this.ExecuteWithTracer(enlistment, tracer, metadata, commandId); + } + finally + { + tracer.Stop(metadata); } + } + } - // Now default to the current working directory when running the verb without a specified path - if (string.IsNullOrEmpty(this.Directory) || this.Directory.Equals(".")) + private 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)) { - 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; - } + 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; } + } - 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"] = "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"] = cache.Info == null ? "LegacyCache" + : cache.Info.CountsComplete ? "Success" : "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"] = 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)) { - 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 + { + // 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 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++) { - return null; + 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..b88e61d3ca --- /dev/null +++ b/docs/hydration-status-diagnostics.md @@ -0,0 +1,93 @@ +# 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. + +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 phase. +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. +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. +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 is an integer from `CacheState`. +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. + +## 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. + +This contract does not change count sets, disk-log replay, percentages, cache acceptance, or 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 --------------------------- From 75f1fed22afcc821da669880fa71d6f0f29ff197 Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Fri, 23 Oct 2026 11:20:39 -0700 Subject: [PATCH 2/4] Correct hydration diagnostic policy boundaries and strengthen contract tests Preserve cached summaries and circuit-breaker counts when configuration reads fail. Preserve cancellation policy while recording cancellation origin. Separate command outcome from calculation outcome and name the heartbeat cache-state point sample explicitly. Pin IPC state integers and add regression tests for source-loader orchestration, failed phases, worker timeouts, cache snapshots, real command paths, and collector payloads. Assisted-by: GPT-6.1 Sol Signed-off-by: Tyrie Vella --- GVFS/GVFS.Common/GitStatusCache.cs | 59 +++-- .../EnlistmentHydrationSummary.cs | 8 +- .../HealthCalculator/EnlistmentPathData.cs | 48 ++-- .../HydrationStatusCircuitBreaker.cs | 4 +- .../HydrationSummaryDiagnostics.cs | 2 + .../HydrationStatusNamedPipeMessages.cs | 19 +- .../GVFS.Common/NamedPipes/NamedPipeClient.cs | 8 +- .../Tests/EnlistmentPerFixture/HealthTests.cs | 89 +++++++- .../Common/EnlistmentHydrationSummaryTests.cs | 122 +++++++++- .../Common/EnlistmentPathDiagnosticsTests.cs | 166 ++++++++++++++ .../Common/GitStatusCacheTests.cs | 214 ++++++++++++++++++ .../Common/HydrationStatusDiagnosticsTests.cs | 208 ++++++++++++++++- .../Mock/Common/MockNamedPipeClient.cs | 50 ++++ .../TelemetryDaemonEventListenerTests.cs | 100 ++++++-- GVFS/GVFS/CommandLine/HealthVerb.cs | 68 ++++-- docs/hydration-status-diagnostics.md | 28 ++- 16 files changed, 1074 insertions(+), 119 deletions(-) create mode 100644 GVFS/GVFS.UnitTests/Common/EnlistmentPathDiagnosticsTests.cs create mode 100644 GVFS/GVFS.UnitTests/Mock/Common/MockNamedPipeClient.cs diff --git a/GVFS/GVFS.Common/GitStatusCache.cs b/GVFS/GVFS.Common/GitStatusCache.cs index d28544df4d..369adda87c 100644 --- a/GVFS/GVFS.Common/GitStatusCache.cs +++ b/GVFS/GVFS.Common/GitStatusCache.cs @@ -291,7 +291,7 @@ public virtual bool WriteTelemetryandReset(EventMetadata metadata) { metadata["HydrationStatus.RequestCount"] = hydrationRequests; metadata["HydrationStatus.UnavailableCount"] = hydrationUnavailable; - metadata["HydrationStatus.CacheState"] = this.hydrationCache.State; + metadata["HydrationStatus.CurrentCacheState"] = this.hydrationCache.State; wroteTelemetry = true; } @@ -456,31 +456,27 @@ private void RebuildStatusCacheIfNeeded(bool ignoreBackoff) internal void UpdateHydrationSummary() { - HydrationStatusCircuitBreaker circuitBreaker = new HydrationStatusCircuitBreaker( - this.context.Enlistment.DotGVFSRoot, - this.context.Tracer); - try + if (this.projectedFolderCountProvider == null) { - if (this.projectedFolderCountProvider == null) - { - this.RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState.ProviderUnavailable); - return; - } + this.RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState.ProviderUnavailable); + return; + } - bool enabled = TEST_EnableHydrationSummaryOverride - ?? this.context.Repository.LibGit2RepoInvoker.GetConfigBoolOrDefault(GVFSConstants.GitConfig.ShowHydrationStatus, GVFSConstants.GitConfig.ShowHydrationStatusDefault); - if (!enabled) - { - this.RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState.FeatureDisabled); - return; - } + if (!this.GetHydrationSummaryEnabled()) + { + this.RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState.FeatureDisabled); + return; + } - if (circuitBreaker.IsDisabled()) - { - this.RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState.CircuitBreakerDisabled); - return; - } + HydrationStatusCircuitBreaker circuitBreaker = this.CreateHydrationCircuitBreaker(); + if (circuitBreaker.IsDisabled()) + { + this.RecordHydrationSkip(NamedPipeMessages.HydrationStatus.CacheState.CircuitBreakerDisabled); + return; + } + try + { /* While not strictly part of git status, enlistment hydration summary is used * in "git status" pre-command hook, and can take several seconds to compute on very large repos. * Accessing it here ensures that the value is cached for when a user invokes "git status", @@ -493,7 +489,7 @@ internal void UpdateHydrationSummary() FolderCountSource = HydrationFolderCountSource.Projection, }; EnlistmentHydrationSummary hydrationSummary = - EnlistmentHydrationSummary.CreateSummary(this.context.Enlistment, this.context.FileSystem, this.context.Tracer, this.projectedFolderCountProvider, this.shutdownTokenSource.Token, diagnostics); + 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 @@ -547,6 +543,23 @@ internal void UpdateHydrationSummary() } } + 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; diff --git a/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs b/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs index bfacee4885..9c605af1d4 100644 --- a/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs +++ b/GVFS/GVFS.Common/HealthCalculator/EnlistmentHydrationSummary.cs @@ -102,7 +102,8 @@ internal static EnlistmentHydrationSummary CreateSummary( { summary.TotalFolderCount = 0; diagnostics.EarlyExit = true; - diagnostics.Outcome = HydrationSummaryOutcome.InvalidCounts; + diagnostics.Outcome = diagnostics.IndexState == HydrationDataState.Failed + ? HydrationSummaryOutcome.IncompleteData : HydrationSummaryOutcome.InvalidCounts; return summary; } @@ -115,9 +116,12 @@ internal static EnlistmentHydrationSummary CreateSummary( : diagnostics.CountsComplete ? HydrationSummaryOutcome.Success : HydrationSummaryOutcome.IncompleteData; return summary; } - catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) + catch (OperationCanceledException e) { 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(); diff --git a/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs b/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs index a87d571413..ed76e811d1 100644 --- a/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs +++ b/GVFS/GVFS.Common/HealthCalculator/EnlistmentPathData.cs @@ -51,14 +51,7 @@ public void NormalizeAllPaths() /// The current GVFS enlistment being operated on public virtual void LoadPlaceholdersFromDatabase(GVFSEnlistment enlistment, HydrationSummaryDiagnostics diagnostics = null) { - List filePlaceholders = new List(); - List folderPlaceholders = new List(); - - using (GVFSDatabase database = new GVFSDatabase(new PhysicalFileSystem(), enlistment.DotGVFSRoot, new SqliteDatabase())) - { - PlaceholderTable placeholderTable = new PlaceholderTable(database); - placeholderTable.GetAllEntries(out filePlaceholders, out folderPlaceholders); - } + this.ReadPlaceholderEntries(enlistment, out List filePlaceholders, out List folderPlaceholders); this.PlaceholderFilePaths.AddRange(filePlaceholders.Select(placeholderData => placeholderData.Path)); if (diagnostics != null) @@ -136,15 +129,11 @@ public virtual 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)); - if (diagnostics != null) - { - diagnostics.ModifiedPathsDiskOutcome = HydrationPathSourceOutcome.Success; - diagnostics.ModifiedPathsState = HydrationDataState.Complete; - } + diagnostics.ModifiedPathsDiskOutcome = HydrationPathSourceOutcome.Success; + diagnostics.ModifiedPathsState = HydrationDataState.Complete; } } catch (Exception ex) @@ -162,6 +151,31 @@ public virtual void LoadModifiedPaths(GVFSEnlistment enlistment, ITracer tracer, } } + 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); + } + } + + 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) @@ -206,7 +220,7 @@ internal IEnumerable ReadModifiedPathDatabaseLines(StreamReader r, Hydra /// An array containing all of the modified paths in string format 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(); 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 index cc2bde307c..eecbb7c0c3 100644 --- a/GVFS/GVFS.Common/HealthCalculator/HydrationSummaryDiagnostics.cs +++ b/GVFS/GVFS.Common/HealthCalculator/HydrationSummaryDiagnostics.cs @@ -113,6 +113,7 @@ public sealed class HydrationSummaryDiagnostics 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; } @@ -213,6 +214,7 @@ public EventMetadata GetMetadata() [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, }; diff --git a/GVFS/GVFS.Common/NamedPipes/HydrationStatusNamedPipeMessages.cs b/GVFS/GVFS.Common/NamedPipes/HydrationStatusNamedPipeMessages.cs index d1cd16fb0a..53259fc2cf 100644 --- a/GVFS/GVFS.Common/NamedPipes/HydrationStatusNamedPipeMessages.cs +++ b/GVFS/GVFS.Common/NamedPipes/HydrationStatusNamedPipeMessages.cs @@ -13,15 +13,15 @@ public static class HydrationStatus public enum CacheState { - NotComputed, - Available, - ProviderUnavailable, - FeatureDisabled, - CircuitBreakerDisabled, - InvalidCounts, - IncompleteData, - Cancelled, - Failed, + NotComputed = 0, + Available = 1, + ProviderUnavailable = 2, + FeatureDisabled = 3, + CircuitBreakerDisabled = 4, + InvalidCounts = 5, + IncompleteData = 6, + Cancelled = 7, + Failed = 8, } public enum ParseOutcome @@ -84,6 +84,7 @@ public static bool TryParse(string body, out CacheInfo info, bool hasCounts = fa /// /// Wire format: PlaceholderFileCount,PlaceholderFolderCount,ModifiedFileCount,ModifiedFolderCount,TotalFileCount,TotalFolderCount + /// An optional D1 extension follows the six counts. CacheInfo defines the extension fields. /// public class Response { diff --git a/GVFS/GVFS.Common/NamedPipes/NamedPipeClient.cs b/GVFS/GVFS.Common/NamedPipes/NamedPipeClient.cs index caa4cc137e..54c282ae49 100644 --- a/GVFS/GVFS.Common/NamedPipes/NamedPipeClient.cs +++ b/GVFS/GVFS.Common/NamedPipes/NamedPipeClient.cs @@ -21,7 +21,7 @@ public bool Connect(int timeoutMilliseconds = 3000) return this.Connect(timeoutMilliseconds, out _); } - public bool Connect(int timeoutMilliseconds, out Exception error) + public virtual bool Connect(int timeoutMilliseconds, out Exception error) { error = null; if (this.clientStream != null) @@ -65,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()); } @@ -102,7 +102,7 @@ public string ReadRawResponse() } } - public NamedPipeMessages.Message ReadResponse() + public virtual NamedPipeMessages.Message ReadResponse() { return NamedPipeMessages.Message.FromString(this.ReadRawResponse()); } @@ -121,7 +121,7 @@ public bool TryReadResponse(out NamedPipeMessages.Message message) } } - public void Dispose() + public virtual void Dispose() { this.ValidateConnection(); diff --git a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs index 52254cfebe..56d96ca454 100644 --- a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs +++ b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs @@ -10,6 +10,7 @@ using System.Text.RegularExpressions; using System.Linq; using System.Text.Json; +using System.Threading; namespace GVFS.FunctionalTests.Tests.EnlistmentPerFixture { @@ -142,6 +143,7 @@ public void FilterIntoDirectory() [TestCase, Order(5)] public void StatusRecordsTheDisplayedResultAndFallbackDiagnostics() { + this.RemountWithHydrationStatus(false); HashSet previousLogs = new HashSet(Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log")); string output = this.Enlistment.Health(statusOnly: true); string log = Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log").Single(path => !previousLogs.Contains(path)); @@ -153,23 +155,90 @@ public void StatusRecordsTheDisplayedResultAndFallbackDiagnostics() 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().ShouldNotBeNull(); + 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."); - if (root.GetProperty("ResultSource").GetString() == "Fallback") + root.GetProperty("ResultSource").GetString().ShouldEqual("Fallback"); + string calculation = lines.Single(line => line.Contains("HydrationSummaryDuration ")); + using (JsonDocument calculationDocument = JsonDocument.Parse(calculation.Substring(calculation.IndexOf('{')))) { - 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)) + { + 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); + Stopwatch deadline = Stopwatch.StartNew(); + string lastCompletion = string.Empty; + while (deadline.Elapsed < TimeSpan.FromSeconds(30)) + { + HashSet previous = new HashSet(Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log")); + string output = this.Enlistment.Health(statusOnly: true); + using (JsonDocument completion = this.ReadHealthCompletion(previous)) + { + JsonElement root = completion.RootElement; + lastCompletion = root.GetRawText(); + if (root.GetProperty("ResultSource").GetString() == "Cache") { - 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); + 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 "); + return; } } + + Thread.Sleep(100); } + + Assert.Fail("The mount did not publish a valid hydration summary. Last completion: " + lastCompletion); + } + + private void RemountWithHydrationStatus(bool enabled) + { + this.Enlistment.UnmountGVFS(); + GitProcess.InvokeProcess(this.Enlistment.RepoRoot, "config --local gvfs.show-hydration-status " + (enabled ? "true" : "false")).ExitCode.ShouldEqual(0); + this.Enlistment.MountGVFS(); + GitProcess.InvokeProcess(this.Enlistment.RepoRoot, "status --porcelain").ExitCode.ShouldEqual(0); + this.Enlistment.WaitForBackgroundOperations(); + } + + private JsonDocument ReadHealthCompletion(HashSet previous) + { + string log = Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log").Single(path => !previous.Contains(path)); + string line = File.ReadAllLines(log).Single(value => value.Contains("health (Stop)")); + return JsonDocument.Parse(line.Substring(line.IndexOf('{'))); } private void HydratePlaceholder(string filePath) diff --git a/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs b/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs index 772799c3d3..99ead1c816 100644 --- a/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs +++ b/GVFS/GVFS.UnitTests/Common/EnlistmentHydrationSummaryTests.cs @@ -339,6 +339,7 @@ public void CalculationEmitsCountsAndFinalValidity(int folderCount, string outco 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; @@ -376,6 +377,13 @@ public void FailureRetainsEarlierAndPartialCounts(HydrationSummaryPhase phase) 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) @@ -383,7 +391,9 @@ public void FailureRetainsEarlierAndPartialCounts(HydrationSummaryPhase phase) Assert.AreEqual(3, summary.Diagnostics.ModifiedFileCount); } - string payload = telemetry.Events.Single(e => e.EventName == "HydrationSummaryDuration").Payload; + 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")); @@ -425,6 +435,8 @@ public void EarlyExitLeavesFolderCountAndTimingUnavailable() 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); @@ -442,6 +454,9 @@ public void CancellationRetainsSuccessfulObservations() 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); @@ -452,19 +467,116 @@ public void CancellationRetainsSuccessfulObservations() [TestCase] [Category(CategoryConstants.ExceptionExpected)] - public void UnrelatedCancellationExceptionIsFailure() + 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.IsNotNull(summary.Error); + 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()); } - private void AddIndex(int count) + [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); @@ -477,6 +589,7 @@ private sealed class TestPathData : EnlistmentPathData 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) { @@ -499,6 +612,7 @@ public override void LoadModifiedPaths(GVFSEnlistment enlistment, ITracer tracer } diagnostics.ModifiedPathsState = this.ModifiedState; + this.DuringModifiedPaths?.Invoke(); if (this.FailurePhase == HydrationSummaryPhase.ModifiedPaths) { throw new IOException("mock:\\private\\modified {secret}"); 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 26f0567bc1..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 { @@ -114,6 +116,218 @@ public void DisabledHydrationFeatureExplainsTheCacheMiss() } } + [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 index 26c1cca53c..3416b97ca1 100644 --- a/GVFS/GVFS.UnitTests/Common/HydrationStatusDiagnosticsTests.cs +++ b/GVFS/GVFS.UnitTests/Common/HydrationStatusDiagnosticsTests.cs @@ -7,6 +7,9 @@ using System; using System.IO; using System.Linq; +using System.Collections.Generic; +using System.Threading; +using GVFS.UnitTests.Category; namespace GVFS.UnitTests.Common { @@ -35,7 +38,7 @@ public void CacheExtensionPreservesLegacyCountPrefix() CountsComplete = true, }; string body = response.ToBody(info); - Assert.That(body, Does.StartWith("1,2,3,4,100,50,D1,")); + 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)); @@ -104,7 +107,8 @@ public void CachedDisplayRecordsCountsWithoutFallback() verb.OutputHydrationPercent(null, tracer, metadata, Guid.NewGuid()); Assert.AreEqual("Cache", metadata["ResultSource"]); Assert.AreEqual("Percentage", metadata["DisplayOutcome"]); - Assert.AreEqual("LegacyCache", metadata["Outcome"]); + 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"]); @@ -112,6 +116,206 @@ public void CachedDisplayRecordsCountsWithoutFallback() } } + [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() { 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 8d3030fd4b..3c9ced2ac8 100644 --- a/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs +++ b/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs @@ -10,47 +10,101 @@ 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] - public async Task HydrationMetadataReachesTheCollectorWithNullsAndNestedCounts() + [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); - HydrationSummaryDiagnostics diagnostics = new HydrationSummaryDiagnostics - { - TotalFileCount = 100, - ModifiedFileCount = 0, - Outcome = HydrationSummaryOutcome.Failed, - ExceptionType = typeof(IOException).FullName, - }; - using (JsonTracer tracer = new JsonTracer("test", "test", disableTelemetry: true)) + 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)); - tracer.RelatedEvent(EventLevel.Warning, "HydrationSummaryDuration", - new EventMetadata { ["Summary"] = diagnostics.GetMetadata() }, Keywords.Telemetry); + CollectorHealthVerb verb = new CollectorHealthVerb { StatusOnly = true, CacheHit = cacheHit, Output = output }; + verb.ExecuteWithCompletion(null, tracer, Guid.NewGuid()); } - string line = (await received).Split('\n')[0]; - TelemetryDaemonEventListener.PipeMessage envelope = TelemetryDaemonEventListener.PipeMessage.FromJson(line); - Assert.AreEqual("HydrationSummaryDuration", envelope.EventName); - Assert.AreEqual("test-enlistment", envelope.Payload.EnlistmentId); - using (JsonDocument json = JsonDocument.Parse(envelope.Payload.Json)) + 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 summary = json.RootElement.GetProperty("Summary"); - Assert.AreEqual(100, summary.GetProperty("TotalFileCount").GetInt32()); - Assert.AreEqual(0, summary.GetProperty("ModifiedFileCount").GetInt32()); - Assert.AreEqual(JsonValueKind.Null, summary.GetProperty("TotalFolderCount").ValueKind); - Assert.AreEqual("Failed", summary.GetProperty("Outcome").GetString()); - Assert.AreEqual(diagnostics.CalculationId.ToString("N"), summary.GetProperty("CalculationId").GetString()); + 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"); } } diff --git a/GVFS/GVFS/CommandLine/HealthVerb.cs b/GVFS/GVFS/CommandLine/HealthVerb.cs index 17b595c904..a6128dd8e3 100644 --- a/GVFS/GVFS/CommandLine/HealthVerb.cs +++ b/GVFS/GVFS/CommandLine/HealthVerb.cs @@ -71,25 +71,38 @@ protected override void Execute(GVFSEnlistment enlistment) Keywords.Any); Guid commandId = Guid.NewGuid(); - EventMetadata metadata = new EventMetadata - { - ["SchemaVersion"] = 1, - ["CommandId"] = commandId.ToString("N"), - ["Mode"] = this.StatusOnly ? "Status" : "Detailed", - ["Outcome"] = "Failed", - }; - try - { - this.ExecuteWithTracer(enlistment, tracer, metadata, commandId); - } - finally - { - tracer.Stop(metadata); - } + 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); } } - private void ExecuteWithTracer(GVFSEnlistment enlistment, ITracer tracer, EventMetadata metadata, Guid commandId) + internal virtual void ExecuteWithTracer(GVFSEnlistment enlistment, ITracer tracer, EventMetadata metadata, Guid commandId) { if (this.StatusOnly) { @@ -127,7 +140,7 @@ private void ExecuteWithTracer(GVFSEnlistment enlistment, ITracer tracer, EventM EnlistmentHealthData enlistmentHealthData = enlistmentHealthCalculator.CalculateStatistics(this.Directory); this.PrintOutput(enlistmentHealthData); - metadata["Outcome"] = "Success"; + metadata["Outcome"] = HealthCommandOutcome.Success; } internal void OutputHydrationPercent(GVFSEnlistment enlistment, ITracer tracer, EventMetadata metadata, Guid commandId) @@ -143,8 +156,9 @@ internal void OutputHydrationPercent(GVFSEnlistment enlistment, ITracer tracer, { metadata["ResultSource"] = "Cache"; metadata["DisplayOutcome"] = "Percentage"; - metadata["Outcome"] = cache.Info == null ? "LegacyCache" - : cache.Info.CountsComplete ? "Success" : "IncompleteData"; + 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; @@ -160,7 +174,8 @@ internal void OutputHydrationPercent(GVFSEnlistment enlistment, ITracer tracer, EnlistmentHydrationSummary summary = this.CreateHydrationSummary(enlistment, tracer, diagnostics); metadata["Summary"] = diagnostics.GetMetadata(); metadata["CalculationId"] = diagnostics.CalculationId.ToString("N"); - metadata["Outcome"] = diagnostics.Outcome; + metadata["Outcome"] = summary.IsValid ? HealthCommandOutcome.Success : HealthCommandOutcome.Failed; + metadata["CalculationOutcome"] = diagnostics.Outcome; metadata["DisplayOutcome"] = summary.IsValid ? "Percentage" : "Error"; this.Output.WriteLine(summary.ToMessage()); } @@ -182,7 +197,7 @@ internal virtual CacheLookupResult TryGetCachedHydrationStatus(GVFSEnlistment en { try { - using (NamedPipeClient pipeClient = new NamedPipeClient(enlistment.NamedPipeName)) + using (NamedPipeClient pipeClient = this.CreateHydrationPipeClient(enlistment)) { if (!pipeClient.Connect(ConnectTimeoutMs, out Exception error)) { @@ -223,6 +238,17 @@ internal virtual CacheLookupResult TryGetCachedHydrationStatus(GVFSEnlistment en 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 }; diff --git a/docs/hydration-status-diagnostics.md b/docs/hydration-status-diagnostics.md index b88e61d3ca..b37195a924 100644 --- a/docs/hydration-status-diagnostics.md +++ b/docs/hydration-status-diagnostics.md @@ -9,6 +9,9 @@ The diagnostic fields describe both attempts without a repository path or a raw `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. +This terminal record replaces the generic exception telemetry and the early-exit warning. The six count fields contain numbers or JSON null. A null value means that the calculation did not obtain that count. @@ -21,13 +24,16 @@ Partial counts remain available, but their source state is not `Complete`. `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 phase. +`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. @@ -40,6 +46,9 @@ They do not change its replay semantics or the recursive meaning of modified-fol 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. @@ -58,7 +67,20 @@ D1,state,calculationId,ageMs,invalidated,countsComplete ``` An `NA` response can contain this extension without counts. -The state is an integer from `CacheState`. +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`. @@ -71,6 +93,7 @@ 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 @@ -82,6 +105,7 @@ The modified-path reader retains its existing connection and response-wait behav Telemetry contains exception types and HRESULT values, not arbitrary exception messages or stacks. Local warnings retain full exception details. +Hydration exceptions no longer produce generic Error-level telemetry or telemetry warnings with full exception text. The structured result fields are identical in local logs and telemetry. Raw details appear only in local warnings. From d800cfe84fc88fefc459424aed7eb892ac85d46d Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Fri, 23 Oct 2026 12:36:50 -0700 Subject: [PATCH 3/4] Wait for hydration cache state in health functional tests Poll the structured cache state before checking disabled and available results. Filesystem background readiness does not guarantee that the hydration refresh passed its backoff. Keep the deadline bounded and retain the final completion record on failure. Add functional test cases with zero-second and five-second cache backoff. Keep product behavior unchanged. Assisted-by: GPT-6.1 Sol Signed-off-by: Tyrie Vella --- .../Tests/EnlistmentPerFixture/HealthTests.cs | 103 +++++++++--------- 1 file changed, 53 insertions(+), 50 deletions(-) diff --git a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs index 56d96ca454..f8c122861b 100644 --- a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs +++ b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs @@ -140,38 +140,31 @@ public void FilterIntoDirectory() enlistmentHealthStatus: "Highly Hydrated"); } - [TestCase, Order(5)] - public void StatusRecordsTheDisplayedResultAndFallbackDiagnostics() + [TestCase(0), Order(5)] + [TestCase(5)] + public void StatusRecordsTheDisplayedResultAndFallbackDiagnostics(int backoffSeconds) { - this.RemountWithHydrationStatus(false); - HashSet previousLogs = new HashSet(Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log")); - string output = this.Enlistment.Health(statusOnly: true); - string log = Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log").Single(path => !previousLogs.Contains(path)); - string[] lines = File.ReadAllLines(log); - string completion = lines.Single(line => line.Contains("health (Stop)")); - using (JsonDocument document = JsonDocument.Parse(completion.Substring(completion.IndexOf('{')))) + 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 root = document.RootElement; - 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); - } + 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); } } @@ -180,7 +173,7 @@ public void DetailedHealthRecordsItsCommandMode() { HashSet previous = new HashSet(Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log")); this.Enlistment.Health(); - using (JsonDocument completion = this.ReadHealthCompletion(previous)) + using (JsonDocument completion = this.ReadHealthCompletion(previous, out _)) { completion.RootElement.GetProperty("Mode").GetString().ShouldEqual("Detailed"); completion.RootElement.GetProperty("Outcome").GetString().ShouldEqual("Success"); @@ -192,52 +185,62 @@ public void DetailedHealthRecordsItsCommandMode() 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")); - string output = this.Enlistment.Health(statusOnly: true); - using (JsonDocument completion = this.ReadHealthCompletion(previous)) + output = this.Enlistment.Health(statusOnly: true); + using (JsonDocument completion = this.ReadHealthCompletion(previous, out lines)) { JsonElement root = completion.RootElement; lastCompletion = root.GetRawText(); - if (root.GetProperty("ResultSource").GetString() == "Cache") + if (root.GetProperty("Cache").GetProperty("State").GetString() == expectedState) { - 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 "); - return; + return root.Clone(); } } Thread.Sleep(100); } - Assert.Fail("The mount did not publish a valid hydration summary. Last completion: " + lastCompletion); + throw new AssertionException("The hydration cache did not reach " + expectedState + ". Last completion: " + lastCompletion); } - private void RemountWithHydrationStatus(bool enabled) + 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) + private JsonDocument ReadHealthCompletion(HashSet previous, out string[] lines) { string log = Directory.GetFiles(this.Enlistment.GVFSLogsRoot, "gvfs_health_*.log").Single(path => !previous.Contains(path)); - string line = File.ReadAllLines(log).Single(value => value.Contains("health (Stop)")); + lines = File.ReadAllLines(log); + string line = lines.Single(value => value.Contains("health (Stop)")); return JsonDocument.Parse(line.Substring(line.IndexOf('{'))); } From f543d02e52096902e9b407e783f6ba5a0476c70c Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Wed, 28 Oct 2026 13:49:41 -0700 Subject: [PATCH 4/4] docs: state the durable hydration diagnostic contract Keep telemetry replacement history in the pull request description. State the count, cache, and circuit-breaker preservation requirement directly in the diagnostic contract. Assisted-by: GPT-6.1 Sol Signed-off-by: Tyrie Vella --- docs/hydration-status-diagnostics.md | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/docs/hydration-status-diagnostics.md b/docs/hydration-status-diagnostics.md index b37195a924..4423e459b5 100644 --- a/docs/hydration-status-diagnostics.md +++ b/docs/hydration-status-diagnostics.md @@ -11,7 +11,6 @@ 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. -This terminal record replaces the generic exception telemetry and the early-exit warning. The six count fields contain numbers or JSON null. A null value means that the calculation did not obtain that count. @@ -105,7 +104,6 @@ The modified-path reader retains its existing connection and response-wait behav Telemetry contains exception types and HRESULT values, not arbitrary exception messages or stacks. Local warnings retain full exception details. -Hydration exceptions no longer produce generic Error-level telemetry or telemetry warnings with full exception text. The structured result fields are identical in local logs and telemetry. Raw details appear only in local warnings. @@ -114,4 +112,4 @@ The listener can drop events when its queue is full or its collector is unavaila Process termination can also prevent a terminal record. Mount telemetry cannot observe a hook connection failure that never reaches the mount. -This contract does not change count sets, disk-log replay, percentages, cache acceptance, or circuit-breaker policy. +Diagnostic collection must preserve count sets, disk-log replay, percentages, cache acceptance, and circuit-breaker policy.