From 1c62255933f105057e6ec5c21facfbda3ef79edc Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Wed, 28 Oct 2026 15:58:40 -0700 Subject: [PATCH 1/2] Bound repeated failure and eviction telemetry Keep diagnostic samples and exact per-layer observation counts on the telemetry pipe. Preserve direct local error logs and retry behavior. Distinguish direct breaker rejections from companion errors. Use AggregationResult without changes to legacy HRESULT fields. Add regression tests for counter keys, disposal delivery, cache-lock boundaries, breaker-state observations, and requestor annotations. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Assisted-by: GPT-6.1 Sol Signed-off-by: Tyrie Vella --- .../CircuitBreakerOpenException.cs | 10 + GVFS/GVFS.Common/Git/GVFSGitObjects.cs | 28 ++- GVFS/GVFS.Common/Git/GitObjects.cs | 1 + GVFS/GVFS.Common/Http/ConfigHttpRequestor.cs | 2 +- .../Http/GitObjectsHttpRequestor.cs | 8 +- GVFS/GVFS.Common/MissingTreeTracker.cs | 79 +++++-- GVFS/GVFS.Common/RetryCircuitBreaker.cs | 41 ++++ GVFS/GVFS.Common/RetryWrapper.cs | 23 ++- GVFS/GVFS.Common/Tracing/EventMetadata.cs | 12 ++ GVFS/GVFS.Common/Tracing/JsonTracer.cs | 3 +- .../Tracing/TelemetryAggregation.cs | 34 +++ .../Tracing/TelemetryAggregator.cs | 144 +++++++++++++ .../Tracing/TelemetryDaemonEventListener.cs | 13 +- GVFS/GVFS.Common/Tracing/TraceEventMessage.cs | 1 + GVFS/GVFS.Hooks/GVFS.Hooks.csproj | 3 + .../WindowsFileSystemVirtualizer.cs | 10 +- .../Common/MissingTreeTrackerTests.cs | 69 +++++++ .../Common/RetryWrapperTests.cs | 130 ++++++++++++ .../GVFS.UnitTests/Git/GVFSGitObjectsTests.cs | 71 ++++++- GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs | 31 +++ .../Http/GitObjectsHttpRequestorTests.cs | 38 ++++ .../Mock/Git/MockGVFSGitObjects.cs | 19 +- .../Projection/MockGitIndexProjection.cs | 11 + .../Tracing/TelemetryAggregatorTests.cs | 195 ++++++++++++++++++ .../TelemetryDaemonEventListenerTests.cs | 152 ++++++++++++++ .../Projection/SortedFolderEntriesTests.cs | 60 ++++++ .../WindowsFileSystemVirtualizerTests.cs | 46 +++++ .../GitIndexProjection.FolderData.cs | 1 + 28 files changed, 1201 insertions(+), 34 deletions(-) create mode 100644 GVFS/GVFS.Common/CircuitBreakerOpenException.cs create mode 100644 GVFS/GVFS.Common/Tracing/TelemetryAggregation.cs create mode 100644 GVFS/GVFS.Common/Tracing/TelemetryAggregator.cs create mode 100644 GVFS/GVFS.UnitTests/Tracing/TelemetryAggregatorTests.cs diff --git a/GVFS/GVFS.Common/CircuitBreakerOpenException.cs b/GVFS/GVFS.Common/CircuitBreakerOpenException.cs new file mode 100644 index 0000000000..212ac54031 --- /dev/null +++ b/GVFS/GVFS.Common/CircuitBreakerOpenException.cs @@ -0,0 +1,10 @@ +namespace GVFS.Common +{ + public class CircuitBreakerOpenException : RetryableException + { + public CircuitBreakerOpenException() + : base("Circuit breaker is open - too many consecutive failures. Fast-failing to prevent resource exhaustion.") + { + } + } +} diff --git a/GVFS/GVFS.Common/Git/GVFSGitObjects.cs b/GVFS/GVFS.Common/Git/GVFSGitObjects.cs index 06a1af9908..43a39febd7 100644 --- a/GVFS/GVFS.Common/Git/GVFSGitObjects.cs +++ b/GVFS/GVFS.Common/Git/GVFSGitObjects.cs @@ -67,13 +67,15 @@ public enum BlobHydrationFailureCategory /// internal class DownloadAttemptResult { - public DownloadAttemptResult(DownloadAndSaveObjectResult result, HttpStatusCode? httpStatusCode) + public DownloadAttemptResult(DownloadAndSaveObjectResult result, HttpStatusCode? httpStatusCode, bool circuitBreakerRejected = false) { this.Result = result; this.HttpStatusCode = httpStatusCode; + this.CircuitBreakerRejected = circuitBreakerRejected; } public DownloadAndSaveObjectResult Result { get; } + public bool CircuitBreakerRejected { get; } // The HTTP status of the last download attempt, or null when no HTTP response was // received (for example an exhausted retry that ended in an exception). @@ -87,7 +89,8 @@ public virtual bool TryCopyBlobContentStream( CancellationToken cancellationToken, RequestSource requestSource, Action writeAction, - out BlobHydrationFailureCategory failureCategory) + out BlobHydrationFailureCategory failureCategory, + EventMetadata failureMetadata = null) { // Short-circuit a malformed SHA (for example a corrupt placeholder's all-NUL // content-id) before the retry loop. GitRepo already rejects it as a clean miss, @@ -117,8 +120,9 @@ public virtual bool TryCopyBlobContentStream( DownloadAttemptResult lastDownloadResult = null; bool downloadSucceededButCopyFailed = false; BlobHydrationFailureCategory capturedCategory = BlobHydrationFailureCategory.None; + TelemetryFailureCategory? capturedTelemetryCategory = null; - RetryWrapper retrier = new RetryWrapper(this.GitObjectRequestor.RetryConfig.MaxAttempts, cancellationToken); + RetryWrapper retrier = new RetryWrapper(this.GitObjectRequestor.RetryConfig.MaxAttempts, cancellationToken, tracer: this.Tracer); retrier.OnFailure += errorArgs => { @@ -165,6 +169,17 @@ public virtual bool TryCopyBlobContentStream( capturedCategory = category; metadata.Add(nameof(BlobHydrationFailureCategory), category.ToString()); + capturedTelemetryCategory = + errorArgs.Error is CircuitBreakerOpenException || (errorArgs.Error == null && lastDownloadResult?.CircuitBreakerRejected == true) + ? TelemetryFailureCategory.CircuitBreakerOpen + : (category == BlobHydrationFailureCategory.NetworkUnavailable ? TelemetryFailureCategory.NetworkUnavailable : null); + if (capturedTelemetryCategory.HasValue) + { + metadata.SetTelemetryAggregation( + nameof(this.TryCopyBlobContentStream), + capturedTelemetryCategory.Value, + errorArgs.Error is CircuitBreakerOpenException ? "Rejected" : "Failed"); + } // Surface the HTTP status of the last download attempt so telemetry can tell a // genuine auth failure (401/400/302) apart from a transient one (408/5xx/503), @@ -222,6 +237,11 @@ public virtual bool TryCopyBlobContentStream( }); failureCategory = invokeResult.Result ? BlobHydrationFailureCategory.None : capturedCategory; + if (!invokeResult.Result && capturedTelemetryCategory.HasValue && failureMetadata != null) + { + failureMetadata.SetTelemetryAggregation(nameof(this.TryCopyBlobContentStream), capturedTelemetryCategory.Value, "Failed"); + } + return invokeResult.Result; } @@ -377,7 +397,7 @@ private DownloadAttemptResult DoDownloadAndSaveObject( } } - return new DownloadAttemptResult(DownloadAndSaveObjectResult.Error, httpStatusCode); + return new DownloadAttemptResult(DownloadAndSaveObjectResult.Error, httpStatusCode, output.Error is CircuitBreakerOpenException); } } } \ No newline at end of file diff --git a/GVFS/GVFS.Common/Git/GitObjects.cs b/GVFS/GVFS.Common/Git/GitObjects.cs index 19c1a0e608..47a27bb55e 100644 --- a/GVFS/GVFS.Common/Git/GitObjects.cs +++ b/GVFS/GVFS.Common/Git/GitObjects.cs @@ -70,6 +70,7 @@ public virtual bool TryDownloadCommit(string commitSha) EventMetadata metadata = CreateEventMetadata(eArgs.Error); metadata.Add("Operation", "DownloadAndSaveObjects"); metadata.Add("WillRetry", eArgs.WillRetry); + eArgs.AddTelemetryMetadata(metadata, "DownloadAndSaveObjects"); if (eArgs.WillRetry) { diff --git a/GVFS/GVFS.Common/Http/ConfigHttpRequestor.cs b/GVFS/GVFS.Common/Http/ConfigHttpRequestor.cs index 95b531bb36..689b611184 100644 --- a/GVFS/GVFS.Common/Http/ConfigHttpRequestor.cs +++ b/GVFS/GVFS.Common/Http/ConfigHttpRequestor.cs @@ -41,7 +41,7 @@ public bool TryQueryGVFSConfig(bool logErrors, out ServerGVFSConfig serverGVFSCo } long requestId = HttpRequestor.GetNewRequestId(); - RetryWrapper retrier = new RetryWrapper(this.RetryConfig.MaxAttempts, CancellationToken.None); + RetryWrapper retrier = new RetryWrapper(this.RetryConfig.MaxAttempts, CancellationToken.None, tracer: logErrors ? this.Tracer : null); if (logErrors) { diff --git a/GVFS/GVFS.Common/Http/GitObjectsHttpRequestor.cs b/GVFS/GVFS.Common/Http/GitObjectsHttpRequestor.cs index 278351b8ee..9ae963899f 100644 --- a/GVFS/GVFS.Common/Http/GitObjectsHttpRequestor.cs +++ b/GVFS/GVFS.Common/Http/GitObjectsHttpRequestor.cs @@ -58,7 +58,8 @@ public virtual List QueryForFileSizes(IEnumerable objectI RetryWrapper> retrier = new RetryWrapper>( this.RetryConfig.MaxAttempts + (hasEndpointOverride && !useOrigin ? 2 : 0), - cancellationToken); + cancellationToken, + tracer: this.Tracer); retrier.OnFailure += RetryWrapper>.StandardErrorHandler(this.Tracer, requestId, "QueryFileSizes"); RetryWrapper>.InvocationResult requestTask = retrier.Invoke( @@ -161,7 +162,7 @@ public virtual GitRefs QueryInfoRefs(string branch) return null; } - RetryWrapper retrier = new RetryWrapper(this.RetryConfig.MaxAttempts, CancellationToken.None); + RetryWrapper retrier = new RetryWrapper(this.RetryConfig.MaxAttempts, CancellationToken.None, tracer: this.Tracer); retrier.OnFailure += RetryWrapper.StandardErrorHandler(this.Tracer, requestId, "QueryInfoRefs"); RetryWrapper.InvocationResult output = retrier.Invoke( @@ -362,7 +363,8 @@ public virtual RetryWrapper.InvocationResult TrySendProtoco RetryWrapper retrier = new RetryWrapper( (retryOnFailure ? this.RetryConfig.MaxAttempts : 1) + (hasFallbackEndPoint ? 1 : 0), - cancellationToken); + cancellationToken, + tracer: this.Tracer); if (onFailure != null) { retrier.OnFailure += onFailure; diff --git a/GVFS/GVFS.Common/MissingTreeTracker.cs b/GVFS/GVFS.Common/MissingTreeTracker.cs index fe17c98908..5d0dfc8798 100644 --- a/GVFS/GVFS.Common/MissingTreeTracker.cs +++ b/GVFS/GVFS.Common/MissingTreeTracker.cs @@ -45,11 +45,14 @@ public MissingTreeTracker(ITracer tracer, int treeCapacity) /// public void AddMissingRootTree(string treeSha, string commitSha) { + EvictionTelemetry telemetry = default; lock (this.syncLock) { this.EnsureCommitTracked(commitSha); - this.AddTreeToCommit(treeSha, commitSha); + this.AddTreeToCommit(treeSha, commitSha, ref telemetry); } + + this.TraceEvictions(telemetry); } /// @@ -58,6 +61,7 @@ public void AddMissingRootTree(string treeSha, string commitSha) /// public void AddMissingSubTrees(string parentTreeSha, string[] subTreeShas) { + EvictionTelemetry telemetry = default; lock (this.syncLock) { if (!this.commitsByTree.TryGetValue(parentTreeSha, out var commits)) @@ -78,10 +82,12 @@ public void AddMissingSubTrees(string parentTreeSha, string[] subTreeShas) } /* Ensure we don't evict this commit while trying to add a tree to it. */ this.MarkCommitAsUsed(commitSha); - this.AddTreeToCommit(subTreeSha, commitSha); + this.AddTreeToCommit(subTreeSha, commitSha, ref telemetry); } } } + + this.TraceEvictions(telemetry); } /// @@ -167,7 +173,7 @@ private void EnsureCommitTracked(string commitSha) } } - private void AddTreeToCommit(string treeSha, string commitSha) + private void AddTreeToCommit(string treeSha, string commitSha, ref EvictionTelemetry telemetry) { if (!this.commitsByTree.ContainsKey(treeSha)) { @@ -175,7 +181,7 @@ private void AddTreeToCommit(string treeSha, string commitSha) while (this.commitsByTree.Count >= this.treeCapacity) { // If evict fails it means we only have one commit left. - if (!this.EvictLruCommit()) + if (!this.EvictLruCommit(ref telemetry)) { break; } @@ -198,7 +204,7 @@ private void MarkCommitAsUsed(string commitSha) } } - private bool EvictLruCommit() + private bool EvictLruCommit(ref EvictionTelemetry telemetry) { var last = this.commitOrder.Last; if (last != null && last.Value != this.commitOrder.First.Value) @@ -207,25 +213,66 @@ private bool EvictLruCommit() var treeCountBefore = this.commitsByTree.Count; this.RemoveCommitNoCache(lruCommit); - EventMetadata metadata = new EventMetadata(); - metadata.Add("Area", EtwArea); - metadata.Add("EvictedCommit", lruCommit); - metadata.Add("TreeCountBefore", treeCountBefore); - metadata.Add("TreeCountAfter", this.commitsByTree.Count); - this.tracer.RelatedEvent(EventLevel.Informational, nameof(this.EvictLruCommit), metadata, Keywords.Telemetry); + if (telemetry.SuccessCount++ == 0) + { + telemetry.EvictedCommit = lruCommit; + telemetry.TreeCountBefore = treeCountBefore; + telemetry.TreeCountAfter = this.commitsByTree.Count; + } return true; } - EventMetadata warnMetadata = new EventMetadata(); - warnMetadata.Add("Area", EtwArea); - warnMetadata.Add("TreeCount", this.commitsByTree.Count); - warnMetadata.Add("CommitCount", this.commitNodes.Count); - this.tracer.RelatedEvent(EventLevel.Warning, $"{nameof(this.EvictLruCommit)}CouldNotEvict", warnMetadata, Keywords.Telemetry); + if (telemetry.FailureCount++ == 0) + { + telemetry.FailedTreeCount = this.commitsByTree.Count; + telemetry.FailedCommitCount = this.commitNodes.Count; + } return false; } + private void TraceEvictions(EvictionTelemetry telemetry) + { + if (telemetry.SuccessCount > 0) + { + EventMetadata metadata = new EventMetadata + { + { "Area", EtwArea }, + { "EvictedCommit", telemetry.EvictedCommit }, + { "TreeCountBefore", telemetry.TreeCountBefore }, + { "TreeCountAfter", telemetry.TreeCountAfter }, + { "EvictionCount", telemetry.SuccessCount }, + }; + metadata.SetTelemetryAggregation(nameof(this.EvictLruCommit), TelemetryFailureCategory.None, "Succeeded", telemetry.SuccessCount); + this.tracer.RelatedEvent(EventLevel.Informational, nameof(this.EvictLruCommit), metadata, Keywords.Telemetry); + } + + if (telemetry.FailureCount > 0) + { + EventMetadata metadata = new EventMetadata + { + { "Area", EtwArea }, + { "TreeCount", telemetry.FailedTreeCount }, + { "CommitCount", telemetry.FailedCommitCount }, + { "CouldNotEvictCount", telemetry.FailureCount }, + }; + metadata.SetTelemetryAggregation(nameof(this.EvictLruCommit), TelemetryFailureCategory.EvictionUnavailable, "CouldNotEvict", telemetry.FailureCount); + this.tracer.RelatedEvent(EventLevel.Warning, $"{nameof(this.EvictLruCommit)}CouldNotEvict", metadata, Keywords.Telemetry); + } + } + + private struct EvictionTelemetry + { + public long SuccessCount; + public long FailureCount; + public string EvictedCommit; + public int TreeCountBefore; + public int TreeCountAfter; + public int FailedTreeCount; + public int FailedCommitCount; + } + /// /// Removes a commit without cascading tree removal to other commits. /// Used during LRU eviction: the trees are still missing, so other commits diff --git a/GVFS/GVFS.Common/RetryCircuitBreaker.cs b/GVFS/GVFS.Common/RetryCircuitBreaker.cs index 0f294c10ee..6012e72f62 100644 --- a/GVFS/GVFS.Common/RetryCircuitBreaker.cs +++ b/GVFS/GVFS.Common/RetryCircuitBreaker.cs @@ -1,5 +1,6 @@ using System; using System.Threading; +using GVFS.Common.Tracing; namespace GVFS.Common { @@ -18,6 +19,7 @@ public static class RetryCircuitBreaker private static int cooldownMs = DefaultCooldownMs; private static int consecutiveFailures = 0; private static long circuitOpenedAtUtcTicks = 0; + private static int observedState = -1; public static bool IsOpen { @@ -49,6 +51,44 @@ public static void RecordFailure() } } + internal static void TraceState(ITracer tracer, bool isOpen, string trigger) + { + if (tracer == null) + { + return; + } + + DateTime observedAtUtc = DateTime.UtcNow; + int state = isOpen ? 1 : 0; + if (!isOpen && ConsecutiveFailures >= failureThreshold) + { + long openedAt = Volatile.Read(ref circuitOpenedAtUtcTicks); + if (openedAt == 0 || observedAtUtc.Ticks - openedAt < TimeSpan.FromMilliseconds(cooldownMs).Ticks) + { + return; + } + + state = 2; + } + + int previousState = Interlocked.Exchange(ref observedState, state); + if (previousState == state) + { + return; + } + + string[] states = { "Accepting", "Rejecting", "CooldownElapsed" }; + EventMetadata metadata = new EventMetadata + { + { "PreviousState", previousState < 0 ? "Unknown" : states[previousState] }, + { "State", states[state] }, + { "Trigger", trigger }, + { "ObservedAtUtc", observedAtUtc.ToString("O") }, + }; + metadata.SetTelemetryAggregation(nameof(RetryCircuitBreaker), TelemetryFailureCategory.BreakerState, states[state]); + tracer.RelatedEvent(EventLevel.Informational, "RetryCircuitBreakerState", metadata, Keywords.Telemetry); + } + /// /// Resets the circuit breaker to its initial state. Intended for testing. /// @@ -58,6 +98,7 @@ public static void Reset() Volatile.Write(ref circuitOpenedAtUtcTicks, 0); Volatile.Write(ref failureThreshold, DefaultFailureThreshold); Volatile.Write(ref cooldownMs, DefaultCooldownMs); + Volatile.Write(ref observedState, -1); } /// diff --git a/GVFS/GVFS.Common/RetryWrapper.cs b/GVFS/GVFS.Common/RetryWrapper.cs index 4d56ccc1fa..28dcf0c779 100644 --- a/GVFS/GVFS.Common/RetryWrapper.cs +++ b/GVFS/GVFS.Common/RetryWrapper.cs @@ -13,12 +13,14 @@ public class RetryWrapper private readonly int maxAttempts; private readonly double exponentialBackoffBase; private readonly CancellationToken cancellationToken; + private readonly ITracer tracer; - public RetryWrapper(int maxAttempts, CancellationToken cancellationToken, double exponentialBackoffBase = RetryBackoff.DefaultExponentialBackoffBase) + public RetryWrapper(int maxAttempts, CancellationToken cancellationToken, double exponentialBackoffBase = RetryBackoff.DefaultExponentialBackoffBase, ITracer tracer = null) { this.maxAttempts = maxAttempts; this.cancellationToken = cancellationToken; this.exponentialBackoffBase = exponentialBackoffBase; + this.tracer = tracer; } public event Action OnFailure = delegate { }; @@ -32,6 +34,7 @@ public static Action StandardErrorHandler(ITracer tracer, long r metadata.Add("AttemptNumber", eArgs.TryCount); metadata.Add("Operation", actionName); metadata.Add("WillRetry", eArgs.WillRetry); + eArgs.AddTelemetryMetadata(metadata, actionName); string message = null; if (eArgs.Error != null) { @@ -70,10 +73,11 @@ public InvocationResult Invoke(Func toInvoke) // likelihood of sustained pool exhaustion. If telemetry shows this // cascade occurring, consider excluding local resource pressure (pool // timeouts) from circuit breaker failure counts. - if (RetryCircuitBreaker.IsOpen) + bool circuitIsOpen = RetryCircuitBreaker.IsOpen; + RetryCircuitBreaker.TraceState(this.tracer, circuitIsOpen, "Invocation"); + if (circuitIsOpen) { - RetryableException circuitOpenError = new RetryableException( - "Circuit breaker is open - too many consecutive failures. Fast-failing to prevent resource exhaustion."); + CircuitBreakerOpenException circuitOpenError = new CircuitBreakerOpenException(); this.OnFailure(new ErrorEventArgs(circuitOpenError, tryCount: 1, willRetry: false)); return new InvocationResult(1, circuitOpenError); } @@ -91,6 +95,7 @@ public InvocationResult Invoke(Func toInvoke) if (result.ShouldRecordFailure) { RetryCircuitBreaker.RecordFailure(); + RetryCircuitBreaker.TraceState(this.tracer, RetryCircuitBreaker.IsOpen, "Failure"); } if (!this.ShouldRetry(tryCount, null, result)) @@ -101,6 +106,7 @@ public InvocationResult Invoke(Func toInvoke) else { RetryCircuitBreaker.RecordSuccess(); + RetryCircuitBreaker.TraceState(this.tracer, RetryCircuitBreaker.IsOpen, "Success"); return new InvocationResult(tryCount, true, result.Result); } } @@ -117,6 +123,7 @@ e is AggregateException } RetryCircuitBreaker.RecordFailure(); + RetryCircuitBreaker.TraceState(this.tracer, RetryCircuitBreaker.IsOpen, "Failure"); if (!this.ShouldRetry(tryCount, exceptionToReport, null)) { return new InvocationResult(tryCount, exceptionToReport); @@ -182,6 +189,14 @@ public ErrorEventArgs(Exception error, int tryCount, bool willRetry) public int TryCount { get; } public Exception Error { get; } + + public void AddTelemetryMetadata(EventMetadata metadata, string operation) + { + if (this.Error is CircuitBreakerOpenException) + { + metadata.SetTelemetryAggregation(operation, TelemetryFailureCategory.CircuitBreakerOpen, "Rejected"); + } + } } public class InvocationResult diff --git a/GVFS/GVFS.Common/Tracing/EventMetadata.cs b/GVFS/GVFS.Common/Tracing/EventMetadata.cs index 73f51de0bd..994ac27a92 100644 --- a/GVFS/GVFS.Common/Tracing/EventMetadata.cs +++ b/GVFS/GVFS.Common/Tracing/EventMetadata.cs @@ -14,5 +14,17 @@ public EventMetadata(Dictionary metadata) : base(metadata) { } + + public TelemetryAggregation TelemetryAggregation { get; private set; } + + public void SetTelemetryAggregation(string operation, TelemetryFailureCategory failureCategory, string result, long count = 1) + { + this.TelemetryAggregation = new TelemetryAggregation(operation, failureCategory, result, count); + this["TelemetrySchemaVersion"] = GVFS.Common.Tracing.TelemetryAggregation.SchemaVersion; + this["TelemetryAggregation"] = "Sample"; + this["Operation"] = operation; + this["FailureCategory"] = failureCategory.ToString(); + this["AggregationResult"] = result; + } } } diff --git a/GVFS/GVFS.Common/Tracing/JsonTracer.cs b/GVFS/GVFS.Common/Tracing/JsonTracer.cs index 80bd53f3a1..4fb59f0c47 100644 --- a/GVFS/GVFS.Common/Tracing/JsonTracer.cs +++ b/GVFS/GVFS.Common/Tracing/JsonTracer.cs @@ -394,7 +394,8 @@ private void WriteEvent(string eventName, EventLevel level, Keywords keywords, E Level = level, Keywords = keywords, Opcode = opcode, - Payload = jsonPayload + Payload = jsonPayload, + TelemetryAggregation = metadata?.TelemetryAggregation, }; // Iterating over the bag is thread-safe as the enumerator returned here diff --git a/GVFS/GVFS.Common/Tracing/TelemetryAggregation.cs b/GVFS/GVFS.Common/Tracing/TelemetryAggregation.cs new file mode 100644 index 0000000000..951df6f164 --- /dev/null +++ b/GVFS/GVFS.Common/Tracing/TelemetryAggregation.cs @@ -0,0 +1,34 @@ +using System; + +namespace GVFS.Common.Tracing +{ + public enum TelemetryFailureCategory + { + CircuitBreakerOpen, + NetworkUnavailable, + SizesUnavailable, + MissingObjectSize, + None, + EvictionUnavailable, + BreakerState, + } + + public sealed class TelemetryAggregation + { + internal const int SchemaVersion = 2; + + public TelemetryAggregation(string operation, TelemetryFailureCategory failureCategory, string result, long count = 1) + { + ArgumentOutOfRangeException.ThrowIfNegativeOrZero(count); + this.Operation = operation; + this.FailureCategory = failureCategory; + this.Result = result; + this.Count = count; + } + + public string Operation { get; } + public TelemetryFailureCategory FailureCategory { get; } + public string Result { get; } + public long Count { get; } + } +} diff --git a/GVFS/GVFS.Common/Tracing/TelemetryAggregator.cs b/GVFS/GVFS.Common/Tracing/TelemetryAggregator.cs new file mode 100644 index 0000000000..693d3e75e3 --- /dev/null +++ b/GVFS/GVFS.Common/Tracing/TelemetryAggregator.cs @@ -0,0 +1,144 @@ +using System; +using System.Collections.Generic; + +namespace GVFS.Common.Tracing +{ + internal sealed class TelemetryAggregator + { + internal const int Capacity = 64; + private static readonly TimeSpan Interval = TimeSpan.FromSeconds(60); + + private readonly object gate = new object(); + private readonly TimeProvider timeProvider; + private readonly Dictionary<(string EventName, string Operation, string Category, string Result), Counter> counters = new Dictionary<(string, string, string, string), Counter>(); + private Counter overflow; + private long intervalStarted; + + public TelemetryAggregator(TimeProvider timeProvider = null) + { + this.timeProvider = timeProvider ?? TimeProvider.System; + this.intervalStarted = this.timeProvider.GetTimestamp(); + } + + public void Record(TraceEventMessage message, Action emit) + { + List completed = null; + DateTime now; + bool sample = true; + lock (this.gate) + { + now = this.timeProvider.GetUtcNow().UtcDateTime; + if (this.timeProvider.GetElapsedTime(this.intervalStarted) >= Interval) + { + completed = this.Drain(); + } + + TelemetryAggregation aggregation = message.TelemetryAggregation; + if (aggregation != null) + { + (string, string, string, string) key = (message.EventName, aggregation.Operation, aggregation.FailureCategory.ToString(), aggregation.Result); + if (!this.counters.TryGetValue(key, out Counter counter)) + { + if (this.counters.Count < Capacity) + { + counter = new Counter(key, now); + this.counters.Add(key, counter); + } + else + { + this.overflow = this.overflow ?? new Counter(("Overflow", "Overflow", "Overflow", "Overflow"), now); + counter = this.overflow; + } + } + + sample = counter.ObservedCount == 0 && counter != this.overflow; + counter.ObservedCount += aggregation.Count; + if (sample) + { + ++counter.SampleCount; + } + } + } + + EmitSummaries(completed, now, emit); + if (sample) + { + emit(message); + } + } + + public void Flush(Action emit) + { + List completed; + lock (this.gate) + { + completed = this.Drain(); + } + + EmitSummaries(completed, this.timeProvider.GetUtcNow().UtcDateTime, emit); + } + + private static void EmitSummaries(List completed, DateTime now, Action emit) + { + if (completed == null) + { + return; + } + + foreach (Counter counter in completed) + { + EventMetadata metadata = new EventMetadata + { + { "TelemetrySchemaVersion", TelemetryAggregation.SchemaVersion }, + { "TelemetryAggregation", "Summary" }, + { "OriginalEventName", counter.Key.EventName }, + { "Operation", counter.Key.Operation }, + { "FailureCategory", counter.Key.Category }, + { "AggregationResult", counter.Key.Result }, + { "ObservedCount", counter.ObservedCount }, + { "SampleCount", counter.SampleCount }, + { "SuppressedCount", counter.ObservedCount - counter.SampleCount }, + { "IntervalStartUtc", counter.StartedAtUtc.ToString("O") }, + { "IntervalEndUtc", now.ToString("O") }, + { "OverflowCount", counter.Key.EventName == "Overflow" ? counter.ObservedCount : 0L }, + }; + emit(new TraceEventMessage + { + EventName = "TelemetrySummary", + Level = EventLevel.Informational, + Keywords = Keywords.Telemetry, + Opcode = EventOpcode.Info, + Payload = EventMetadataConverter.SerializeToString(metadata), + }); + } + } + + private List Drain() + { + List completed = new List(this.counters.Values); + if (this.overflow != null) + { + completed.Add(this.overflow); + this.overflow = null; + } + + this.counters.Clear(); + this.intervalStarted = this.timeProvider.GetTimestamp(); + return completed; + } + + private sealed class Counter + { + public Counter((string EventName, string Operation, string Category, string Result) key, DateTime startedAtUtc) + { + this.Key = key; + this.StartedAtUtc = startedAtUtc; + } + + public (string EventName, string Operation, string Category, string Result) Key { get; } + public DateTime StartedAtUtc { get; } + public long ObservedCount { get; set; } + public long SampleCount { get; set; } + } + } +} diff --git a/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs b/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs index 69e50d3fae..7c8a6a18b0 100644 --- a/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs +++ b/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs @@ -13,15 +13,17 @@ public class TelemetryDaemonEventListener : EventListener, IQueuedPipeStringWrit private readonly string mountId; private readonly string vfsVersion; private readonly string vfsArchitecture; + private readonly TelemetryAggregator aggregator; private QueuedPipeStringWriter pipeWriter; - private TelemetryDaemonEventListener( + internal TelemetryDaemonEventListener( string providerName, string enlistmentId, string mountId, string pipeName, - IEventListenerEventSink eventSink) + IEventListenerEventSink eventSink, + TimeProvider timeProvider = null) : base(EventLevel.Verbose, Keywords.Telemetry, eventSink) { this.providerName = providerName; @@ -29,6 +31,7 @@ private TelemetryDaemonEventListener( this.mountId = mountId; this.vfsVersion = ProcessHelper.GetCurrentProcessVersion(); this.vfsArchitecture = ProcessHelper.GetCurrentProcessArchitecture(); + this.aggregator = new TelemetryAggregator(timeProvider); this.pipeWriter = new QueuedPipeStringWriter( () => new NamedPipeClientStream(".", pipeName, PipeDirection.Out, PipeOptions.Asynchronous), @@ -69,6 +72,7 @@ public override void Dispose() { if (this.pipeWriter != null) { + this.aggregator.Flush(this.SendMessage); this.pipeWriter.Stop(); this.pipeWriter.Dispose(); this.pipeWriter = null; @@ -94,6 +98,11 @@ void IQueuedPipeStringWriterEventSink.OnStateChanged( } protected override void RecordMessageInternal(TraceEventMessage message) + { + this.aggregator.Record(message, this.SendMessage); + } + + private void SendMessage(TraceEventMessage message) { string pipeMessage = this.CreatePipeMessage(message); diff --git a/GVFS/GVFS.Common/Tracing/TraceEventMessage.cs b/GVFS/GVFS.Common/Tracing/TraceEventMessage.cs index 742227b72d..bb17291516 100644 --- a/GVFS/GVFS.Common/Tracing/TraceEventMessage.cs +++ b/GVFS/GVFS.Common/Tracing/TraceEventMessage.cs @@ -11,5 +11,6 @@ public class TraceEventMessage public Keywords Keywords { get; set; } public EventOpcode Opcode { get; set; } public string Payload { get; set; } + public TelemetryAggregation TelemetryAggregation { get; set; } } } diff --git a/GVFS/GVFS.Hooks/GVFS.Hooks.csproj b/GVFS/GVFS.Hooks/GVFS.Hooks.csproj index 3b996578e7..f4b54f10d7 100644 --- a/GVFS/GVFS.Hooks/GVFS.Hooks.csproj +++ b/GVFS/GVFS.Hooks/GVFS.Hooks.csproj @@ -86,6 +86,9 @@ Common\Tracing\EventMetadata.cs + + Common\Tracing\TelemetryAggregation.cs + Common\Tracing\EventOpcode.cs diff --git a/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs b/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs index fde263b8a6..7186eb876c 100644 --- a/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs +++ b/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs @@ -1097,6 +1097,7 @@ private void StartDirectoryEnumerationAsyncHandler( EventMetadata metadata = this.CreateEventMetadata(enumerationId, virtualPath, e); metadata.Add("commandId", commandId); metadata.Add(nameof(result), result.ToString("X") + "(" + result.ToString("G") + ")"); + metadata.SetTelemetryAggregation(nameof(this.StartDirectoryEnumerationAsyncHandler), TelemetryFailureCategory.SizesUnavailable, "Failed"); this.Context.Tracer.RelatedError(metadata, nameof(this.StartDirectoryEnumerationAsyncHandler) + ": caught SizesUnavailableException"); } catch (Exception e) @@ -1247,6 +1248,7 @@ private void GetPlaceholderInformationAsyncHandler( metadata.Add("triggeringProcessId", triggeringProcessId); metadata.Add("triggeringProcessImageFileName", triggeringProcessImageFileName); metadata.Add(nameof(result), result.ToString("X") + "(" + result.ToString("G") + ")"); + metadata.SetTelemetryAggregation(nameof(this.GetPlaceholderInformationAsyncHandler), TelemetryFailureCategory.SizesUnavailable, "Failed"); this.Context.Tracer.RelatedError(metadata, nameof(this.GetPlaceholderInformationAsyncHandler) + ": caught SizesUnavailableException"); } catch (Win32Exception e) @@ -1357,9 +1359,15 @@ private void GetFileStreamHandlerAsyncHandler( } } }, - out GVFSGitObjects.BlobHydrationFailureCategory failureCategory)) + out GVFSGitObjects.BlobHydrationFailureCategory failureCategory, + failureMetadata: requestMetadata)) { requestMetadata.Add(nameof(GVFSGitObjects.BlobHydrationFailureCategory), failureCategory.ToString()); + if (requestMetadata.TelemetryAggregation != null) + { + requestMetadata.SetTelemetryAggregation(nameof(this.GetFileStreamHandlerAsyncHandler), requestMetadata.TelemetryAggregation.FailureCategory, "Failed"); + } + this.Context.Tracer.RelatedError(requestMetadata, $"{nameof(this.GetFileStreamHandlerAsyncHandler)}: TryCopyBlobContentStream failed"); this.TryCompleteCommand(commandId, (HResult)HResultExtensions.HResultFromNtStatus.FileNotAvailable); diff --git a/GVFS/GVFS.UnitTests/Common/MissingTreeTrackerTests.cs b/GVFS/GVFS.UnitTests/Common/MissingTreeTrackerTests.cs index a13a345544..b59c0e1016 100644 --- a/GVFS/GVFS.UnitTests/Common/MissingTreeTrackerTests.cs +++ b/GVFS/GVFS.UnitTests/Common/MissingTreeTrackerTests.cs @@ -1,13 +1,82 @@ using GVFS.Common; using GVFS.Tests.Should; using GVFS.UnitTests.Mock.Common; +using GVFS.Common.Tracing; +using System.Linq; using NUnit.Framework; +using System; +using System.Collections.Generic; +using System.Threading.Tasks; namespace GVFS.UnitTests.Common { [TestFixture] public class MissingTreeTrackerTests { + [TestCase] + public void EvictionTelemetryCountsSuccessAndFailureSeparately() + { + MockTracer tracer = new MockTracer(); + MissingTreeTracker tracker = new MissingTreeTracker(tracer, treeCapacity: 1); + tracker.AddMissingRootTree("tree1", "commit1"); + tracker.AddMissingRootTree("tree2", "commit2"); + tracker.AddMissingRootTree("tree3", "commit2"); + tracker.AddMissingSubTrees("tree2", new[] { "tree4", "tree5" }); + + EventMetadata success = tracer.RelatedEventMetadata.Single(metadata => metadata.TelemetryAggregation?.Result == "Succeeded"); + Assert.That(success.TelemetryAggregation.Count, Is.EqualTo(1)); + Assert.That(success["EvictedCommit"], Is.EqualTo("commit1")); + Assert.That(tracer.RelatedEventMetadata + .Where(metadata => metadata.TelemetryAggregation?.Result == "CouldNotEvict") + .Select(metadata => metadata["CouldNotEvictCount"]), Is.EqualTo(new object[] { 1L, 2L })); + Assert.That(tracker.GetHighestMissingTreeCount(new[] { "commit2" }, out _), Is.EqualTo(4)); + } + + [TestCase] + public void MultipleEvictionsEmitOneRepresentativeBatchOutsideTheCacheLock() + { + using (LockCheckingTracer tracer = new LockCheckingTracer()) + { + MissingTreeTracker tracker = new MissingTreeTracker(tracer, treeCapacity: 1); + tracer.Tracker = tracker; + tracker.AddMissingRootTree("sharedTree", "commit1"); + tracker.AddMissingRootTree("sharedTree", "commit2"); + tracker.AddMissingRootTree("sharedTree", "commit3"); + tracker.AddMissingRootTree("newTree", "commit4"); + + EventMetadata metadata = tracer.Events.Single(); + Assert.That(metadata["EvictionCount"], Is.EqualTo(3L)); + Assert.That(metadata.TelemetryAggregation.Count, Is.EqualTo(3)); + Assert.That(metadata["EvictedCommit"], Is.EqualTo("commit1")); + Assert.That(metadata["TreeCountBefore"], Is.EqualTo(1)); + Assert.That(metadata["TreeCountAfter"], Is.EqualTo(1), "The snapshot describes the first removal, not the batch."); + Assert.That(tracker.TryGetCommits("sharedTree", out _), Is.False); + Assert.That(tracker.TryGetCommits("newTree", out string[] commits), Is.True); + Assert.That(commits, Is.EqualTo(new[] { "commit4" })); + } + } + + private sealed class LockCheckingTracer : JsonTracer + { + public LockCheckingTracer() + : base("Microsoft-GVFS-Test", "EvictionLock", disableTelemetry: true) + { + } + + public MissingTreeTracker Tracker { get; set; } + public List Events { get; } = new List(); + + public override void RelatedEvent(EventLevel level, string eventName, EventMetadata metadata, Keywords keyword) + { + if (eventName == "EvictLruCommit") + { + Task probe = Task.Run(() => this.Tracker.GetHighestMissingTreeCount(Array.Empty(), out _)); + Assert.That(probe.Wait(TimeSpan.FromSeconds(5)), Is.True, "Telemetry must not hold the cache lock."); + this.Events.Add(metadata); + } + } + } + private static MissingTreeTracker CreateTracker(int treeCapacity) { return new MissingTreeTracker(new MockTracer(), treeCapacity); diff --git a/GVFS/GVFS.UnitTests/Common/RetryWrapperTests.cs b/GVFS/GVFS.UnitTests/Common/RetryWrapperTests.cs index 528252fa38..b13a7dad1c 100644 --- a/GVFS/GVFS.UnitTests/Common/RetryWrapperTests.cs +++ b/GVFS/GVFS.UnitTests/Common/RetryWrapperTests.cs @@ -1,6 +1,8 @@ using GVFS.Common; using GVFS.Tests.Should; using GVFS.UnitTests.Category; +using GVFS.Common.Tracing; +using GVFS.UnitTests.Mock.Common; using NUnit.Framework; using System; using System.IO; @@ -18,6 +20,134 @@ public void SetUp() RetryCircuitBreaker.Reset(); } + [TearDown] + public void TearDown() + { + RetryCircuitBreaker.Reset(); + } + + [TestCase] + public void LocalRejectionsKeepEveryCustomCallbackAndUseTypedClassification() + { + RetryCircuitBreaker.Configure(1, 30000); + RetryCircuitBreaker.RecordFailure(); + int failures = 0; + RetryWrapper wrapper = new RetryWrapper(5, new CancellationToken(canceled: true)); + wrapper.OnFailure += args => + { + ++failures; + Assert.That(args.Error, Is.TypeOf()); + Assert.That(args.TryCount, Is.EqualTo(1)); + Assert.That(args.WillRetry, Is.False); + EventMetadata metadata = new EventMetadata(); + args.AddTelemetryMetadata(metadata, "CustomDownload"); + Assert.That(metadata.TelemetryAggregation.FailureCategory, Is.EqualTo(TelemetryFailureCategory.CircuitBreakerOpen)); + }; + + for (int i = 0; i < 100; ++i) + { + RetryWrapper.InvocationResult result = wrapper.Invoke(attempt => throw new AssertionException("Local rejection must not invoke the callback.")); + Assert.That(result.Succeeded, Is.False); + Assert.That(result.Attempts, Is.EqualTo(1)); + Assert.That(result.Result, Is.False); + } + + Assert.That(failures, Is.EqualTo(100)); + Assert.That(RetryCircuitBreaker.ConsecutiveFailures, Is.EqualTo(1)); + } + + [TestCase] + public void StandardHandlerDoesNotClassifyMessageLookalikesAsLocalRejections() + { + MockTracer tracer = new MockTracer(); + Action.ErrorEventArgs> handler = RetryWrapper.StandardErrorHandler(tracer, 1, "Download"); + handler(new RetryWrapper.ErrorEventArgs(new IOException(new CircuitBreakerOpenException().Message), 1, false)); + Assert.That(tracer.RelatedErrorEvents[0], Does.Not.Contain("TelemetryAggregation")); + + handler(new RetryWrapper.ErrorEventArgs(new CircuitBreakerOpenException(), 1, false)); + Assert.That(tracer.RelatedErrorEvents[1], Does.Contain("\"FailureCategory\":\"CircuitBreakerOpen\"")); + } + + [TestCase] + public void InconsistentOpenObservationDoesNotFabricateCooldownExpiry() + { + MockTracer tracer = new MockTracer(); + RetryCircuitBreaker.TraceState(tracer, isOpen: false, "Invocation"); + RetryCircuitBreaker.Configure(1, 30000); + RetryCircuitBreaker.RecordFailure(); + RetryCircuitBreaker.TraceState(tracer, isOpen: false, "Invocation"); + Assert.That(tracer.RelatedEventMetadata.Count, Is.EqualTo(1)); + RetryCircuitBreaker.TraceState(tracer, isOpen: true, "Failure"); + Assert.That(tracer.RelatedEventMetadata[1]["State"], Is.EqualTo("Rejecting")); + Assert.That(tracer.RelatedEventMetadata[1]["PreviousState"], Is.EqualTo("Accepting")); + } + + [TestCase(false)] + [TestCase(true)] + [Category(CategoryConstants.ExceptionExpected)] + public void TracedFailuresOpenAndReopenTheBreaker(bool throwError) + { + MockTracer tracer = new MockTracer(); + RetryCircuitBreaker.Configure(1, 30000); + RetryWrapper wrapper = new RetryWrapper(1, CancellationToken.None, tracer: tracer); + Func.CallbackResult> fail = attempt => + { + RetryCircuitBreaker.Configure(1, 30000); + if (throwError) + { + throw new IOException("Synthetic failure"); + } + + return new RetryWrapper.CallbackResult(new IOException("Synthetic failure"), shouldRetry: true); + }; + + wrapper.Invoke(fail); + for (int i = 0; i < 10; ++i) + { + wrapper.Invoke(attempt => throw new AssertionException("An open circuit must reject before the callback.")); + } + + Assert.That(tracer.RelatedEventMetadata.Count, Is.EqualTo(2)); + Assert.That(tracer.RelatedEventMetadata[1]["State"], Is.EqualTo("Rejecting")); + Assert.That(tracer.RelatedEventMetadata[1]["Trigger"], Is.EqualTo("Failure")); + Assert.That(tracer.RelatedEventMetadata[1]["FailureCategory"], Is.EqualTo("BreakerState")); + Assert.That(tracer.RelatedEventMetadata[1]["AggregationResult"], Is.EqualTo("Rejecting")); + + RetryCircuitBreaker.Configure(1, 0); + wrapper.Invoke(fail); + Assert.That(tracer.RelatedEventMetadata.Count, Is.EqualTo(4)); + Assert.That(tracer.RelatedEventMetadata[2]["State"], Is.EqualTo("CooldownElapsed")); + Assert.That(tracer.RelatedEventMetadata[3]["State"], Is.EqualTo("Rejecting")); + Assert.That(tracer.RelatedEventMetadata[3]["Trigger"], Is.EqualTo("Failure")); + } + + [TestCase] + public void CooldownObservationIsNotReportedAsRecovery() + { + MockTracer tracer = new MockTracer(); + RetryCircuitBreaker.Configure(1, 30000); + RetryCircuitBreaker.RecordFailure(); + RetryCircuitBreaker.TraceState(tracer, isOpen: true, "Failure"); + RetryCircuitBreaker.Configure(1, 0); + + RetryWrapper wrapper = new RetryWrapper(1, CancellationToken.None, tracer: tracer); + int callbacks = 0; + wrapper.Invoke(attempt => + { + ++callbacks; + return new RetryWrapper.CallbackResult(new IOException("No response"), shouldRetry: false); + }); + + Assert.That(callbacks, Is.EqualTo(1)); + Assert.That(tracer.RelatedEventMetadata.Count, Is.EqualTo(2)); + Assert.That(tracer.RelatedEventMetadata[1]["State"], Is.EqualTo("CooldownElapsed")); + Assert.That(RetryCircuitBreaker.ConsecutiveFailures, Is.EqualTo(1)); + + wrapper.Invoke(attempt => new RetryWrapper.CallbackResult(true)); + Assert.That(tracer.RelatedEventMetadata[2]["State"], Is.EqualTo("Accepting")); + Assert.That(tracer.RelatedEventMetadata[2]["Trigger"], Is.EqualTo("Success")); + } + [TestCase] [Category(CategoryConstants.ExceptionExpected)] public void WillRetryOnIOException() diff --git a/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs b/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs index 60826ca694..12fc72e600 100644 --- a/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs @@ -51,6 +51,40 @@ public void TearDown() RetryCircuitBreaker.Reset(); } + [TestCase(false)] + [TestCase(true)] + public void LocalBreakerHydrationFailureMarksBothLayersWithoutChangingTheCategory(bool nestedRejection) + { + MockHttpGitObjects httpObjects = new MockHttpGitObjects(); + GVFSGitObjects objects = this.CreateTestableGVFSGitObjects(httpObjects, new MissingBlobGitRepo(), out MockTracer tracer); + if (nestedRejection) + { + httpObjects.RejectWithOpenCircuit = true; + } + else + { + RetryCircuitBreaker.Configure(1, 30000); + RetryCircuitBreaker.RecordFailure(); + } + EventMetadata outerMetadata = new EventMetadata(); + + bool copied = objects.TryCopyBlobContentStream( + ValidTestObjectFileSha1, + CancellationToken.None, + GVFSGitObjects.RequestSource.FileStreamCallback, + (stream, length) => Assert.Fail("Local rejection must not copy a blob."), + out GVFSGitObjects.BlobHydrationFailureCategory category, + failureMetadata: outerMetadata); + + Assert.That(copied, Is.False); + Assert.That(category, Is.EqualTo(nestedRejection ? GVFSGitObjects.BlobHydrationFailureCategory.DownloadFailed : GVFSGitObjects.BlobHydrationFailureCategory.NetworkUnavailable)); + Assert.That(outerMetadata.TelemetryAggregation.FailureCategory, Is.EqualTo(TelemetryFailureCategory.CircuitBreakerOpen)); + Assert.That(outerMetadata["AggregationResult"], Is.EqualTo("Failed")); + Assert.That(tracer.RelatedErrorEvents.Single(), Does.Contain("\"FailureCategory\":\"CircuitBreakerOpen\"")); + Assert.That(tracer.RelatedErrorEvents.Single(), Does.Contain(nestedRejection ? "\"AggregationResult\":\"Failed\"" : "\"AggregationResult\":\"Rejected\"")); + Assert.That(tracer.RelatedEventMetadata, Has.Some.Matches(metadata => metadata.ContainsKey("State") && (string)metadata["State"] == (nestedRejection ? "Accepting" : "Rejecting"))); + } + [TestCase] [Category(CategoryConstants.ExceptionExpected)] public void CatchesFileNotFoundAfterFileDeleted() @@ -196,6 +230,7 @@ public void TerminalBlobHydrationFailureRecordsHttpStatusCode() terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"DownloadFailed\""); terminalError.ShouldContain("\"HttpStatusCode\":401"); terminalError.ShouldContain("\"HttpStatusName\":\"Unauthorized\""); + terminalError.ShouldNotContain(false, "TelemetryAggregation"); } [TestCase] @@ -234,6 +269,7 @@ public void TerminalBlobHydrationFailureRecordsTransientHttpStatusCode() terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"DownloadFailed\""); terminalError.ShouldContain("\"HttpStatusCode\":503"); terminalError.ShouldContain("\"HttpStatusName\":\"ServiceUnavailable\""); + terminalError.ShouldNotContain(false, "TelemetryAggregation"); } [TestCase] @@ -378,17 +414,31 @@ private void AssertRetryableCauseMapsToCategory(RetryableException thrownExcepti MockHttpGitObjects httpObjects = new MockHttpGitObjects(); GVFSGitObjects dut = this.CreateTestableGVFSGitObjects(httpObjects, throwingRepo, out MockTracer tracer); + EventMetadata outerMetadata = new EventMetadata(); bool copied = dut.TryCopyBlobContentStream( ValidTestObjectFileSha1, new CancellationToken(), GVFSGitObjects.RequestSource.FileStreamCallback, (stream, length) => Assert.Fail("Should not be able to call copy stream callback"), - out GVFSGitObjects.BlobHydrationFailureCategory failureCategory); + out GVFSGitObjects.BlobHydrationFailureCategory failureCategory, + failureMetadata: outerMetadata); copied.ShouldEqual(false); failureCategory.ShouldEqual(expected); string terminalError = tracer.RelatedErrorEvents.First(e => e.Contains("Failed to provide blob contents")); terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"" + expected + "\""); + if (expected == GVFSGitObjects.BlobHydrationFailureCategory.NetworkUnavailable) + { + Assert.That(terminalError, Does.Contain("\"FailureCategory\":\"NetworkUnavailable\"")); + Assert.That(terminalError, Does.Contain("\"AggregationResult\":\"Failed\"")); + Assert.That(outerMetadata.TelemetryAggregation.FailureCategory, Is.EqualTo(TelemetryFailureCategory.NetworkUnavailable)); + Assert.That(outerMetadata["AggregationResult"], Is.EqualTo("Failed")); + } + else + { + Assert.That(terminalError, Does.Not.Contain("TelemetryAggregation")); + Assert.That(outerMetadata.TelemetryAggregation, Is.Null); + } } [TestCase] @@ -1055,6 +1105,7 @@ private MockHttpGitObjects(MockGVFSEnlistment enlistment) // i.e. Result is non-null but carries no HTTP status (HttpStatusCodeResult == 0). This // exercises the "download failed without a status" branch of the telemetry status capture. public bool FailWithoutStatus { get; set; } + public bool RejectWithOpenCircuit { get; set; } public byte[] ContentBytesToServe { get; set; } @@ -1093,6 +1144,11 @@ public override RetryWrapper.InvocationResult TryDownloadOb { this.TryDownloadObjectsCallCount++; + if (this.RejectWithOpenCircuit) + { + return new RetryWrapper.InvocationResult(1, new CircuitBreakerOpenException()); + } + if (this.StatusCodeToReturn.HasValue) { // Simulate the server returning a non-OK status (e.g. 404) so callers can exercise @@ -1164,6 +1220,19 @@ public override bool TryCopyBlobContentStream(string blobSha, Action writeAction) + { + return false; + } + } + private class CoalescingTestHttpGitObjects : GitObjectsHttpRequestor { private readonly byte[] objectContents; diff --git a/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs b/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs index 78236a37bc..c5dbcadc7c 100644 --- a/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs @@ -30,6 +30,37 @@ public class GitObjectsTests private readonly List openedPaths = new List(); private readonly Dictionary pathsToData = new Dictionary(); + [TestCase] + public void CommitDownloadCustomHandlerMarksLocalRejections() + { + RetryCircuitBreaker.Reset(); + try + { + MockTracer tracer = new MockTracer(); + MockGVFSEnlistment enlistment = new MockGVFSEnlistment(); + using (GitObjectsHttpRequestor requestor = new GitObjectsHttpRequestor( + tracer, + enlistment, + new CacheServerInfo("mock://cache", "Synthetic", false), + new RetryConfig())) + { + GitObjects objects = new GVFSGitObjects( + new GVFSContext(tracer, new MockFileSystemWithCallbacks(), null, enlistment), + requestor); + RetryCircuitBreaker.Configure(1, 30000); + RetryCircuitBreaker.RecordFailure(); + Assert.That(objects.TryDownloadCommit(RealSha), Is.False); + Assert.That(tracer.RelatedErrorEvents.Count, Is.EqualTo(1)); + Assert.That(tracer.RelatedErrorEvents[0], Does.Contain("\"FailureCategory\":\"CircuitBreakerOpen\"")); + Assert.That(tracer.RelatedErrorEvents[0], Does.Contain("\"Operation\":\"DownloadAndSaveObjects\"")); + } + } + finally + { + RetryCircuitBreaker.Reset(); + } + } + [TestCase] public void WriteLooseObject_DetectsDataNotCompressed() { diff --git a/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs b/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs index ee89a68ae2..778e0f4c06 100644 --- a/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs +++ b/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs @@ -34,6 +34,44 @@ public void TearDown() RetryCircuitBreaker.Reset(); } + [TestCase] + public void FileSizeAndObjectRequestorsObserveOpenBreakerState() + { + RetryCircuitBreaker.Configure(1, 30000); + RetryCircuitBreaker.RecordFailure(); + using (TestGitObjectsHttpRequestor requestor = this.CreateRequestor(maxRetries: 0)) + { + requestor.QueryForFileSizes(new[] { "0123456789abcdef" }, CancellationToken.None); + Assert.That(requestor.TestTracer.RelatedEventNames, Does.Contain("RetryCircuitBreakerState")); + Assert.That(requestor.RequestUris, Is.Empty); + } + + RetryCircuitBreaker.Reset(); + RetryCircuitBreaker.Configure(1, 30000); + RetryCircuitBreaker.RecordFailure(); + using (TestGitObjectsHttpRequestor requestor = this.CreateRequestor(maxRetries: 0)) + { + requestor.TryDownloadLooseObject("0123456789abcdef", false, CancellationToken.None, "test", SuccessfulRequest); + Assert.That(requestor.TestTracer.RelatedEventNames, Does.Contain("RetryCircuitBreakerState")); + Assert.That(requestor.RequestUris, Is.Empty); + } + } + + [TestCase(false)] + [TestCase(true)] + public void ConfigRequestorPreservesSilentErrorPolicy(bool logErrors) + { + MockTracer tracer = new MockTracer(); + RetryCircuitBreaker.Configure(1, 30000); + RetryCircuitBreaker.RecordFailure(); + using (ConfigHttpRequestor requestor = new ConfigHttpRequestor(tracer, new MockGVFSEnlistment(), new RetryConfig(maxRetries: 0))) + { + Assert.That(requestor.TryQueryGVFSConfig(logErrors, out _, out _, out _), Is.False); + Assert.That(tracer.RelatedEventNames.Contains("RetryCircuitBreakerState"), Is.EqualTo(logErrors)); + Assert.That(tracer.RelatedErrorEvents.Count > 0, Is.EqualTo(logErrors)); + } + } + [TestCase] public void LooseObjectFallsBackToGlobalCacheServerWhenEndpointRequestFails() { diff --git a/GVFS/GVFS.UnitTests/Mock/Git/MockGVFSGitObjects.cs b/GVFS/GVFS.UnitTests/Mock/Git/MockGVFSGitObjects.cs index bb34332875..810302488d 100644 --- a/GVFS/GVFS.UnitTests/Mock/Git/MockGVFSGitObjects.cs +++ b/GVFS/GVFS.UnitTests/Mock/Git/MockGVFSGitObjects.cs @@ -1,6 +1,7 @@ using GVFS.Common; using GVFS.Common.Git; using GVFS.Common.Http; +using GVFS.Common.Tracing; using System; using System.Collections.Generic; using System.IO; @@ -22,6 +23,8 @@ public MockGVFSGitObjects(GVFSContext context, GitObjectsHttpRequestor httpGitOb public bool CancelTryCopyBlobContentStream { get; set; } public bool ThrowOnTryCopyBlobContentStream { get; set; } public bool ThrowIOExceptionDuringCopy { get; set; } + public bool RejectHydrationWithOpenCircuit { get; set; } + public bool FailHydrationWithoutAggregation { get; set; } public uint FileLength { get; set; } = DefaultFileLength; public override bool TryDownloadCommit(string objectSha) @@ -46,10 +49,24 @@ public override bool TryCopyBlobContentStream( CancellationToken cancellationToken, RequestSource requestSource, Action writeAction, - out GVFSGitObjects.BlobHydrationFailureCategory failureCategory) + out GVFSGitObjects.BlobHydrationFailureCategory failureCategory, + EventMetadata failureMetadata = null) { failureCategory = GVFSGitObjects.BlobHydrationFailureCategory.None; + if (this.FailHydrationWithoutAggregation) + { + failureCategory = GVFSGitObjects.BlobHydrationFailureCategory.DownloadFailed; + return false; + } + + if (this.RejectHydrationWithOpenCircuit) + { + failureCategory = GVFSGitObjects.BlobHydrationFailureCategory.NetworkUnavailable; + failureMetadata?.SetTelemetryAggregation(nameof(this.TryCopyBlobContentStream), TelemetryFailureCategory.CircuitBreakerOpen, "Failed"); + return false; + } + if (this.CancelTryCopyBlobContentStream) { throw new OperationCanceledException(); diff --git a/GVFS/GVFS.UnitTests/Mock/Virtualization/Projection/MockGitIndexProjection.cs b/GVFS/GVFS.UnitTests/Mock/Virtualization/Projection/MockGitIndexProjection.cs index 143cad6129..1a21928229 100644 --- a/GVFS/GVFS.UnitTests/Mock/Virtualization/Projection/MockGitIndexProjection.cs +++ b/GVFS/GVFS.UnitTests/Mock/Virtualization/Projection/MockGitIndexProjection.cs @@ -62,6 +62,7 @@ public MockGitIndexProjection(IEnumerable projectedFiles) public ConcurrentHashSet SparseEntries { get; } public bool ThrowOperationCanceledExceptionOnProjectionRequest { get; set; } + public bool ThrowSizesUnavailableExceptionOnProjectionRequest { get; set; } public bool ProjectionParseComplete { get; set; } @@ -203,6 +204,11 @@ public override List GetProjectedItems( { this.waitForGetProjectedItems.Set(); + if (this.ThrowSizesUnavailableExceptionOnProjectionRequest) + { + throw new SizesUnavailableException("Synthetic missing size"); + } + if (this.ThrowOperationCanceledExceptionOnProjectionRequest) { throw new OperationCanceledException(); @@ -238,6 +244,11 @@ public override ProjectedFileInfo GetProjectedFileInfo( { this.waitForGetProjectedFileInfo.Set(); + if (this.ThrowSizesUnavailableExceptionOnProjectionRequest) + { + throw new SizesUnavailableException("Synthetic missing size"); + } + if (this.ThrowOperationCanceledExceptionOnProjectionRequest) { throw new OperationCanceledException(); diff --git a/GVFS/GVFS.UnitTests/Tracing/TelemetryAggregatorTests.cs b/GVFS/GVFS.UnitTests/Tracing/TelemetryAggregatorTests.cs new file mode 100644 index 0000000000..40853c9399 --- /dev/null +++ b/GVFS/GVFS.UnitTests/Tracing/TelemetryAggregatorTests.cs @@ -0,0 +1,195 @@ +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Linq; +using System.Text.Json; +using System.Threading.Tasks; +using GVFS.Common.Tracing; +using NUnit.Framework; + +namespace GVFS.UnitTests.Tracing +{ + [TestFixture] + public class TelemetryAggregatorTests + { + [TestCase] + public void StormRetainsOneSampleAndExactIntervalCounters() + { + TestClock clock = new TestClock(); + TelemetryAggregator aggregator = new TelemetryAggregator(clock); + List output = new List(); + clock.Advance(TimeSpan.FromSeconds(5)); + for (int i = 0; i < 10000; ++i) + { + TraceEventMessage message = CreateMessage("QueryFileSizes"); + message.Payload = "{\"RequestId\":" + i + "}"; + aggregator.Record(message, output.Add); + } + + Assert.That(output.Count, Is.EqualTo(1)); + clock.Advance(TimeSpan.FromSeconds(60)); + aggregator.Record(new TraceEventMessage { EventName = "UnfamiliarFailure" }, output.Add); + + Assert.That(output.Select(message => message.EventName), Is.EqualTo(new[] { "NetworkError", "TelemetrySummary", "UnfamiliarFailure" })); + using (JsonDocument summary = JsonDocument.Parse(output[1].Payload)) + { + JsonElement root = summary.RootElement; + AssertCounts(root, 10000, 1, 9999); + Assert.That(root.GetProperty("Operation").GetString(), Is.EqualTo("QueryFileSizes")); + Assert.That(root.GetProperty("IntervalStartUtc").GetDateTime(), Is.EqualTo(clock.UtcStart.AddSeconds(5).UtcDateTime)); + Assert.That(root.GetProperty("IntervalEndUtc").GetDateTime(), Is.EqualTo(clock.UtcStart.AddSeconds(65).UtcDateTime)); + Assert.That(root.TryGetProperty("RequestId", out _), Is.False); + Assert.That(root.GetProperty("OriginalEventName").GetString(), Is.EqualTo("NetworkError")); + Assert.That(root.GetProperty("TelemetrySchemaVersion").GetInt32(), Is.EqualTo(2)); + Assert.That(root.GetProperty("TelemetryAggregation").GetString(), Is.EqualTo("Summary")); + Assert.That(root.GetProperty("AggregationResult").GetString(), Is.EqualTo("Rejected")); + Assert.That(root.GetProperty("OverflowCount").GetInt64(), Is.Zero); + Assert.That(output[1].Level, Is.EqualTo(EventLevel.Informational)); + Assert.That(output[1].Opcode, Is.EqualTo(EventOpcode.Info)); + } + + aggregator.Record(CreateMessage("QueryFileSizes"), output.Add); + Assert.That(output.Count, Is.EqualTo(4), "The new interval permits a fresh sample."); + aggregator.Flush(output.Add); + aggregator.Flush(output.Add); + Assert.That(output.Count, Is.EqualTo(5), "Repeated disposal flushes must not duplicate counters."); + } + + [TestCase] + public void CapacityOverflowIsBoundedAndCountedWithoutHidingUnknownFailures() + { + TelemetryAggregator aggregator = new TelemetryAggregator(); + List output = new List(); + for (int i = 0; i < TelemetryAggregator.Capacity + 100; ++i) + { + aggregator.Record(CreateMessage("Operation" + i), output.Add); + } + + TraceEventMessage unknown = new TraceEventMessage { EventName = "NewNetworkFailure", Payload = "{\"HttpStatusCode\":401}" }; + aggregator.Record(unknown, output.Add); + Assert.That(output.Count, Is.EqualTo(TelemetryAggregator.Capacity + 1)); + Assert.That(output.Last(), Is.SameAs(unknown)); + aggregator.Record(CreateMessage("Operation0"), output.Add); + + aggregator.Flush(output.Add); + Assert.That(output.Count(message => message.EventName == "TelemetrySummary"), Is.EqualTo(TelemetryAggregator.Capacity + 1)); + using (JsonDocument overflow = JsonDocument.Parse(output.Last().Payload)) + { + AssertCounts(overflow.RootElement, 100, 0, 100); + Assert.That(overflow.RootElement.GetProperty("OverflowCount").GetInt64(), Is.EqualTo(100)); + Assert.That(overflow.RootElement.GetProperty("OriginalEventName").GetString(), Is.EqualTo("Overflow")); + Assert.That(overflow.RootElement.GetProperty("Operation").GetString(), Is.EqualTo("Overflow")); + } + + using (JsonDocument tracked = JsonDocument.Parse(output.First(message => message.EventName == "TelemetrySummary").Payload)) + { + AssertCounts(tracked.RootElement, 2, 1, 1); + } + } + + [TestCase] + public void ConcurrentObservationsDoNotDuplicateSamplesOrLoseCounts() + { + TelemetryAggregator aggregator = new TelemetryAggregator(); + ConcurrentQueue output = new ConcurrentQueue(); + Parallel.For(0, 10000, i => aggregator.Record(CreateMessage("Download"), output.Enqueue)); + Assert.That(output.Count, Is.EqualTo(1)); + + aggregator.Flush(output.Enqueue); + using (JsonDocument summary = JsonDocument.Parse(output.Last().Payload)) + { + AssertCounts(summary.RootElement, 10000, 1, 9999); + } + } + + [TestCase] + public void EvictionBatchWeightsKeepSuccessAndFailureSeparate() + { + TelemetryAggregator aggregator = new TelemetryAggregator(); + List output = new List(); + aggregator.Record(CreateMessage("EvictLruCommit", TelemetryFailureCategory.None, "Succeeded", 12), output.Add); + aggregator.Record(CreateMessage("EvictLruCommit", TelemetryFailureCategory.EvictionUnavailable, "CouldNotEvict", 3), output.Add); + aggregator.Flush(output.Add); + + using (JsonDocument success = JsonDocument.Parse(output[2].Payload)) + using (JsonDocument failure = JsonDocument.Parse(output[3].Payload)) + { + AssertCounts(success.RootElement, 12, 1, 11); + AssertCounts(failure.RootElement, 3, 1, 2); + Assert.That(success.RootElement.GetProperty("AggregationResult").GetString(), Is.EqualTo("Succeeded")); + Assert.That(failure.RootElement.GetProperty("AggregationResult").GetString(), Is.EqualTo("CouldNotEvict")); + } + } + + [TestCase("event")] + [TestCase("operation")] + [TestCase("category")] + [TestCase("result")] + public void EachKeyDimensionKeepsItsOwnSample(string dimension) + { + TelemetryAggregator aggregator = new TelemetryAggregator(); + List output = new List(); + TraceEventMessage first = CreateMessage("Download"); + TraceEventMessage second = CreateMessage( + dimension == "operation" ? "QueryFileSizes" : "Download", + dimension == "category" ? TelemetryFailureCategory.NetworkUnavailable : TelemetryFailureCategory.CircuitBreakerOpen, + dimension == "result" ? "Failed" : "Rejected"); + if (dimension == "event") + { + second.EventName = "Error"; + } + + aggregator.Record(first, output.Add); + aggregator.Record(second, output.Add); + aggregator.Record(first, output.Add); + aggregator.Record(second, output.Add); + Assert.That(output.Count, Is.EqualTo(2)); + aggregator.Flush(output.Add); + foreach (TraceEventMessage summary in output.Skip(2)) + { + using (JsonDocument payload = JsonDocument.Parse(summary.Payload)) + { + AssertCounts(payload.RootElement, 2, 1, 1); + } + } + } + + private static TraceEventMessage CreateMessage( + string operation, + TelemetryFailureCategory category = TelemetryFailureCategory.CircuitBreakerOpen, + string result = "Rejected", + long count = 1) + { + return new TraceEventMessage + { + EventName = "NetworkError", + Level = EventLevel.Error, + Keywords = Keywords.Telemetry, + TelemetryAggregation = new TelemetryAggregation(operation, category, result, count), + }; + } + + private static void AssertCounts(JsonElement root, long observed, long sampled, long suppressed) + { + Assert.That(root.GetProperty("ObservedCount").GetInt64(), Is.EqualTo(observed)); + Assert.That(root.GetProperty("SampleCount").GetInt64(), Is.EqualTo(sampled)); + Assert.That(root.GetProperty("SuppressedCount").GetInt64(), Is.EqualTo(suppressed)); + } + + internal sealed class TestClock : TimeProvider + { + private TimeSpan elapsed; + + public DateTimeOffset UtcStart { get; } = new DateTimeOffset(2026, 1, 1, 0, 0, 0, TimeSpan.Zero); + public override long TimestampFrequency => TimeSpan.TicksPerSecond; + + public override DateTimeOffset GetUtcNow() => this.UtcStart + this.elapsed; + public override long GetTimestamp() => this.elapsed.Ticks; + + public void Advance(TimeSpan interval) + { + this.elapsed += interval; + } + } + } +} diff --git a/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs b/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs index f1deffe98f..bcb43547b2 100644 --- a/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs +++ b/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs @@ -4,12 +4,164 @@ using GVFS.Common.Tracing; using GVFS.Tests.Should; using NUnit.Framework; +using System; +using System.IO; +using System.IO.Pipes; +using System.Text; +using System.Threading; +using System.Threading.Tasks; +using GVFS.UnitTests.Mock.Common.Tracing; +using GVFS.UnitTests.Category; namespace GVFS.UnitTests.Tracing { [TestFixture] public class TelemetryDaemonEventListenerTests { + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public async Task RemoteBoundsSurviveARealPipeReconnectAndChildActivities() + { + string pipeName = "gvfs-telemetry-test-" + Guid.NewGuid().ToString("N"); + TelemetryAggregatorTests.TestClock clock = new TelemetryAggregatorTests.TestClock(); + using (CancellationTokenSource timeout = new CancellationTokenSource(TimeSpan.FromSeconds(15))) + using (ListenerFailureSink sink = new ListenerFailureSink()) + using (JsonTracer tracer = new JsonTracer("Microsoft-GVFS-Test", "Root", disableTelemetry: true)) + using (MockListener local = new MockListener(EventLevel.Verbose, Keywords.Any)) + using (TelemetryDaemonEventListener remote = new TelemetryDaemonEventListener("Microsoft.Git.GVFS", "synthetic-enlistment", "synthetic-mount", pipeName, sink, clock)) + { + tracer.AddEventListener(local); + tracer.AddEventListener(remote); + using (NamedPipeServerStream server = CreateServer(pipeName)) + using (StreamReader reader = new StreamReader(server, Encoding.UTF8, false, 1024, leaveOpen: true)) + { + Task connection = server.WaitForConnectionAsync(timeout.Token); + TraceRejection(tracer); + await connection; + Assert.That((await ReadMessage(reader, timeout.Token)).EventName, Is.EqualTo("NetworkError")); + + using (ITracer child = tracer.StartActivity("Child", EventLevel.Informational)) + { + TraceRejection(child); + } + + tracer.RelatedEvent(EventLevel.Informational, "BeforeDisconnect", null, Keywords.Telemetry); + Assert.That((await ReadMessage(reader, timeout.Token)).EventName, Is.EqualTo("BeforeDisconnect")); + } + + tracer.RelatedEvent(EventLevel.Informational, "DetectBrokenPipe", null, Keywords.Telemetry); + Assert.That(sink.Failed.Wait(TimeSpan.FromSeconds(5)), Is.True); + + using (NamedPipeServerStream server = CreateServer(pipeName)) + using (StreamReader reader = new StreamReader(server, Encoding.UTF8, false, 1024, leaveOpen: true)) + { + Task connection = server.WaitForConnectionAsync(timeout.Token); + tracer.RelatedEvent(EventLevel.Informational, "Reconnected", null, Keywords.Telemetry); + await connection; + Assert.That((await ReadMessage(reader, timeout.Token)).EventName, Is.EqualTo("Reconnected")); + TraceRejection(tracer); + clock.Advance(TimeSpan.FromSeconds(60)); + tracer.RelatedEvent(EventLevel.Informational, "Flush", null, Keywords.Telemetry); + TelemetryDaemonEventListener.PipeMessage summary = await ReadMessage(reader, timeout.Token); + Assert.That(summary.EventName, Is.EqualTo("TelemetrySummary")); + Assert.That(summary.Payload.EnlistmentId, Is.EqualTo("synthetic-enlistment")); + Assert.That(summary.Payload.MountId, Is.EqualTo("synthetic-mount")); + using (JsonDocument payload = JsonDocument.Parse(summary.Payload.Json)) + { + Assert.That(payload.RootElement.GetProperty("ObservedCount").GetInt64(), Is.EqualTo(3)); + Assert.That(payload.RootElement.GetProperty("SampleCount").GetInt64(), Is.EqualTo(1)); + Assert.That(payload.RootElement.GetProperty("SuppressedCount").GetInt64(), Is.EqualTo(2)); + } + + Assert.That((await ReadMessage(reader, timeout.Token)).EventName, Is.EqualTo("Flush")); + Assert.That(local.EventNamesRead.Count(name => name == "NetworkError"), Is.EqualTo(3)); + remote.Dispose(); + } + } + } + + [TestCase] + public async Task DisposalDeliversPendingSummaryAndPreservesLegacyResult() + { + string pipeName = "gvfs-telemetry-test-" + Guid.NewGuid().ToString("N"); + using (CancellationTokenSource timeout = new CancellationTokenSource(TimeSpan.FromSeconds(15))) + using (NamedPipeServerStream server = CreateServer(pipeName)) + using (StreamReader reader = new StreamReader(server, Encoding.UTF8, false, 1024, leaveOpen: true)) + using (JsonTracer tracer = new JsonTracer("Microsoft-GVFS-Test", "Root", disableTelemetry: true)) + using (TelemetryDaemonEventListener remote = new TelemetryDaemonEventListener("Microsoft.Git.GVFS", "synthetic-enlistment", "synthetic-mount", pipeName, null)) + { + tracer.AddEventListener(remote); + Task connection = server.WaitForConnectionAsync(timeout.Token); + for (int i = 0; i < 2; ++i) + { + EventMetadata metadata = new EventMetadata { { "result", "0xC0000467" } }; + metadata.SetTelemetryAggregation("StartDirectoryEnumerationAsyncHandler", TelemetryFailureCategory.SizesUnavailable, "Failed"); + tracer.RelatedError(metadata, "Synthetic size unavailable"); + } + + await connection; + TelemetryDaemonEventListener.PipeMessage sample = await ReadMessage(reader, timeout.Token); + using (JsonDocument payload = JsonDocument.Parse(sample.Payload.Json)) + { + Assert.That(payload.RootElement.GetProperty("result").GetString(), Is.EqualTo("0xC0000467")); + Assert.That(payload.RootElement.GetProperty("AggregationResult").GetString(), Is.EqualTo("Failed")); + Assert.That(payload.RootElement.GetProperty("TelemetrySchemaVersion").GetInt32(), Is.EqualTo(2)); + Assert.That(payload.RootElement.GetProperty("TelemetryAggregation").GetString(), Is.EqualTo("Sample")); + Assert.That(payload.RootElement.TryGetProperty("Result", out _), Is.False); + } + + Task disposal = Task.Run(remote.Dispose); + TelemetryDaemonEventListener.PipeMessage summary = await ReadMessage(reader, timeout.Token); + Assert.That(summary.EventName, Is.EqualTo("TelemetrySummary")); + using (JsonDocument payload = JsonDocument.Parse(summary.Payload.Json)) + { + Assert.That(payload.RootElement.GetProperty("ObservedCount").GetInt64(), Is.EqualTo(2)); + Assert.That(payload.RootElement.GetProperty("SampleCount").GetInt64(), Is.EqualTo(1)); + Assert.That(payload.RootElement.GetProperty("SuppressedCount").GetInt64(), Is.EqualTo(1)); + Assert.That(payload.RootElement.GetProperty("AggregationResult").GetString(), Is.EqualTo("Failed")); + } + + await disposal.WaitAsync(timeout.Token); + remote.Dispose(); + } + } + + private static NamedPipeServerStream CreateServer(string pipeName) + { + return new NamedPipeServerStream(pipeName, PipeDirection.In, 1, PipeTransmissionMode.Byte, PipeOptions.Asynchronous); + } + + private static async Task ReadMessage(StreamReader reader, CancellationToken token) + { + return TelemetryDaemonEventListener.PipeMessage.FromJson(await reader.ReadLineAsync(token)); + } + + private static void TraceRejection(ITracer tracer) + { + EventMetadata metadata = new EventMetadata(); + metadata.SetTelemetryAggregation("Download", TelemetryFailureCategory.CircuitBreakerOpen, "Rejected"); + tracer.RelatedError(metadata, "Local rejection", Keywords.Network); + } + + private sealed class ListenerFailureSink : IEventListenerEventSink, IDisposable + { + public ManualResetEventSlim Failed { get; } = new ManualResetEventSlim(); + + public void OnListenerFailure(EventListener listener, string errorMessage) + { + this.Failed.Set(); + } + + public void OnListenerRecovery(EventListener listener) + { + } + + public void Dispose() + { + this.Failed.Dispose(); + } + } + [TestCase] public void TraceMessageDataIsCorrectFormat() { diff --git a/GVFS/GVFS.UnitTests/Virtualization/Projection/SortedFolderEntriesTests.cs b/GVFS/GVFS.UnitTests/Virtualization/Projection/SortedFolderEntriesTests.cs index eff08b5267..c1f29e8f65 100644 --- a/GVFS/GVFS.UnitTests/Virtualization/Projection/SortedFolderEntriesTests.cs +++ b/GVFS/GVFS.UnitTests/Virtualization/Projection/SortedFolderEntriesTests.cs @@ -6,6 +6,14 @@ using System; using System.Collections.Generic; using System.Text; +using System.Threading; +using GVFS.Common.Git; +using GVFS.Common.Http; +using GVFS.UnitTests.Mock.FileSystem; +using GVFS.UnitTests.Mock.Git; +using GVFS.UnitTests.Mock.Virtualization.BlobSize; +using GVFS.Virtualization.BlobSize; +using GVFS.Virtualization.Projection; using static GVFS.Virtualization.Projection.GitIndexProjection; namespace GVFS.UnitTests.Virtualization.Git @@ -71,6 +79,31 @@ public void EmptyFolderEntries_NotFound() folderEntryData.ShouldBeNull(); } + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void MissingRemoteChildSizeKeepsTheFolderIncompleteAndAnnotatesItsError() + { + MockTracer tracer = new MockTracer(); + MockGVFSEnlistment enlistment = new MockGVFSEnlistment(); + MockFileSystemWithCallbacks fileSystem = new MockFileSystemWithCallbacks(); + MockGitRepo repository = new MockGitRepo(tracer, enlistment, fileSystem); + FolderData folder = new FolderData(); + folder.ResetData(ConstructLazyUTF8String("folder"), isIncluded: true); + folder.AddChildFile(ConstructLazyUTF8String("child"), new byte[20]); + using (MissingSizesRequestor requestor = new MissingSizesRequestor(tracer, enlistment)) + using (MissingSizeConnection connection = new MissingSizeConnection()) + { + GVFSGitObjects objects = new GVFSGitObjects(new GVFSContext(tracer, fileSystem, repository, enlistment), requestor); + Assert.Throws(() => folder.PopulateSizes( + tracer, objects, connection, new Dictionary(), CancellationToken.None)); + Assert.That(folder.ChildrenHaveSizes, Is.False); + Assert.That(tracer.RelatedErrorEvents.Count, Is.EqualTo(1)); + Assert.That(tracer.RelatedErrorEvents[0], Does.Contain("\"FailureCategory\":\"MissingObjectSize\"")); + Assert.That(tracer.RelatedErrorEvents[0], Does.Contain("\"Operation\":\"PopulateMissingSizesFromRemote\"")); + Assert.That(tracer.RelatedErrorEvents[0], Does.Contain("\"AggregationResult\":\"Failed\"")); + } + } + [TestCase] public void EntryNotFound() { @@ -297,6 +330,33 @@ private static int GetDefaultEntriesLength() return length; } + private sealed class MissingSizesRequestor : MockHttpGitObjects + { + public MissingSizesRequestor(MockTracer tracer, MockGVFSEnlistment enlistment) + : base(tracer, enlistment) + { + } + + public override List QueryForFileSizes(IEnumerable objectIds, CancellationToken cancellationToken) + { + return new List(); + } + } + + private sealed class MissingSizeConnection : BlobSizes.BlobSizesConnection + { + public MissingSizeConnection() + : base(new MockBlobSizes()) + { + } + + public override bool TryGetSize(Sha1Id sha, out long length) + { + length = 0; + return false; + } + } + private static unsafe LazyUTF8String ConstructLazyUTF8String(string name) { byte[] buffer = Encoding.ASCII.GetBytes(name); diff --git a/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs b/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs index 3a98649b7e..6e46fd9e03 100644 --- a/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs +++ b/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs @@ -737,6 +737,52 @@ public void OnGetFileStreamHandlesCancellationDuringWriteAction() } } + [TestCase(false)] + [TestCase(true)] + public void OnGetFileStreamCompletesFailureWithoutChangingAggregationEligibility(bool aggregate) + { + using (WindowsFileSystemVirtualizerTester tester = new WindowsFileSystemVirtualizerTester(this.Repo)) + { + MockGVFSGitObjects objects = (MockGVFSGitObjects)this.Repo.GitObjects; + objects.RejectHydrationWithOpenCircuit = aggregate; + objects.FailHydrationWithoutAggregation = !aggregate; + tester.InvokeGetFileDataCallback(expectedResult: HResult.Pending); + Assert.That(tester.MockVirtualization.WaitForCompletionStatus(), Is.EqualTo((HResult)HResultExtensions.HResultFromNtStatus.FileNotAvailable)); + + MockTracer tracer = (MockTracer)this.Repo.Context.Tracer; + if (aggregate) + { + Assert.That(tracer.RelatedErrorEvents.Single(), Does.Contain("\"FailureCategory\":\"CircuitBreakerOpen\"")); + Assert.That(tracer.RelatedErrorEvents.Single(), Does.Contain("\"Operation\":\"GetFileStreamHandlerAsyncHandler\"")); + Assert.That(tracer.RelatedErrorEvents.Single(), Does.Contain("\"AggregationResult\":\"Failed\"")); + } + else + { + Assert.That(tracer.RelatedErrorEvents.Single(), Does.Not.Contain("TelemetryAggregation")); + } + } + } + + [TestCase(false)] + [TestCase(true)] + [Category(CategoryConstants.ExceptionExpected)] + public void MissingSizeErrorsRemainFailuresAndUseTypedAggregation(bool enumeration) + { + using (WindowsFileSystemVirtualizerTester tester = new WindowsFileSystemVirtualizerTester(this.Repo)) + { + tester.GitIndexProjection.ThrowSizesUnavailableExceptionOnProjectionRequest = true; + HResult result = enumeration + ? tester.MockVirtualization.RequiredCallbacks.StartDirectoryEnumerationCallback(1, Guid.NewGuid(), "test", TriggeringProcessId, TriggeringProcessImageFileName) + : tester.MockVirtualization.RequiredCallbacks.GetPlaceholderInfoCallback(1, "test.txt", TriggeringProcessId, TriggeringProcessImageFileName); + Assert.That(result, Is.EqualTo(HResult.Pending)); + Assert.That(tester.MockVirtualization.WaitForCompletionStatus(), Is.EqualTo((HResult)HResultExtensions.HResultFromNtStatus.FileNotAvailable)); + + MockTracer tracer = (MockTracer)this.Repo.Context.Tracer; + Assert.That(tracer.RelatedErrorEvents.Single(), Does.Contain("\"FailureCategory\":\"SizesUnavailable\"")); + Assert.That(tester.MockVirtualization.CreatedPlaceholders, Is.Empty); + } + } + [TestCase] public void OnGetFileStreamHandlesWriteFailure() { diff --git a/GVFS/GVFS.Virtualization/Projection/GitIndexProjection.FolderData.cs b/GVFS/GVFS.Virtualization/Projection/GitIndexProjection.FolderData.cs index bf56444a8a..f4866a6b4f 100644 --- a/GVFS/GVFS.Virtualization/Projection/GitIndexProjection.FolderData.cs +++ b/GVFS/GVFS.Virtualization/Projection/GitIndexProjection.FolderData.cs @@ -200,6 +200,7 @@ private void PopulateSizesFromRemote( { EventMetadata metadata = CreateEventMetadata(); metadata.Add("SHA", childNeedingSize.Sha); + metadata.SetTelemetryAggregation("PopulateMissingSizesFromRemote", TelemetryFailureCategory.MissingObjectSize, "Failed"); tracer.RelatedError(metadata, "PopulateMissingSizesFromRemote: Failed to download size for child entry", Keywords.Network); throw new SizesUnavailableException("Failed to download size for " + childNeedingSize.Sha); } From cf1fca67734df736cc35ab876c0da7a3e88bef82 Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Thu, 5 Nov 2026 13:25:09 -0800 Subject: [PATCH 2/2] Preserve telemetry summary scope and breaker transitions Omit command-session context from cross-command summaries. Keep breaker samples separate by previous and destination state. Record the latest observation timestamp in summary counters. Add real-pipe tests for command changes, recovery samples, and bounded repeated transitions. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Assisted-by: GPT-6.1 Sol Signed-off-by: Tyrie Vella --- GVFS/GVFS.Common/RetryCircuitBreaker.cs | 5 +- GVFS/GVFS.Common/Tracing/EventMetadata.cs | 4 +- .../Tracing/TelemetryAggregation.cs | 6 +- .../Tracing/TelemetryAggregator.cs | 22 ++- .../Tracing/TelemetryDaemonEventListener.cs | 3 +- .../Tracing/TelemetryAggregatorTests.cs | 4 +- .../TelemetryDaemonEventListenerTests.cs | 132 +++++++++++++++++- 7 files changed, 161 insertions(+), 15 deletions(-) diff --git a/GVFS/GVFS.Common/RetryCircuitBreaker.cs b/GVFS/GVFS.Common/RetryCircuitBreaker.cs index 6012e72f62..a2957d5b94 100644 --- a/GVFS/GVFS.Common/RetryCircuitBreaker.cs +++ b/GVFS/GVFS.Common/RetryCircuitBreaker.cs @@ -78,14 +78,15 @@ internal static void TraceState(ITracer tracer, bool isOpen, string trigger) } string[] states = { "Accepting", "Rejecting", "CooldownElapsed" }; + string previousStateName = previousState < 0 ? "Unknown" : states[previousState]; EventMetadata metadata = new EventMetadata { - { "PreviousState", previousState < 0 ? "Unknown" : states[previousState] }, + { "PreviousState", previousStateName }, { "State", states[state] }, { "Trigger", trigger }, { "ObservedAtUtc", observedAtUtc.ToString("O") }, }; - metadata.SetTelemetryAggregation(nameof(RetryCircuitBreaker), TelemetryFailureCategory.BreakerState, states[state]); + metadata.SetTelemetryAggregation(nameof(RetryCircuitBreaker), TelemetryFailureCategory.BreakerState, states[state], previousState: previousStateName); tracer.RelatedEvent(EventLevel.Informational, "RetryCircuitBreakerState", metadata, Keywords.Telemetry); } diff --git a/GVFS/GVFS.Common/Tracing/EventMetadata.cs b/GVFS/GVFS.Common/Tracing/EventMetadata.cs index 994ac27a92..0819aaa514 100644 --- a/GVFS/GVFS.Common/Tracing/EventMetadata.cs +++ b/GVFS/GVFS.Common/Tracing/EventMetadata.cs @@ -17,9 +17,9 @@ public EventMetadata(Dictionary metadata) public TelemetryAggregation TelemetryAggregation { get; private set; } - public void SetTelemetryAggregation(string operation, TelemetryFailureCategory failureCategory, string result, long count = 1) + public void SetTelemetryAggregation(string operation, TelemetryFailureCategory failureCategory, string result, long count = 1, string previousState = null) { - this.TelemetryAggregation = new TelemetryAggregation(operation, failureCategory, result, count); + this.TelemetryAggregation = new TelemetryAggregation(operation, failureCategory, result, count, previousState); this["TelemetrySchemaVersion"] = GVFS.Common.Tracing.TelemetryAggregation.SchemaVersion; this["TelemetryAggregation"] = "Sample"; this["Operation"] = operation; diff --git a/GVFS/GVFS.Common/Tracing/TelemetryAggregation.cs b/GVFS/GVFS.Common/Tracing/TelemetryAggregation.cs index 951df6f164..0e89f3c6c0 100644 --- a/GVFS/GVFS.Common/Tracing/TelemetryAggregation.cs +++ b/GVFS/GVFS.Common/Tracing/TelemetryAggregation.cs @@ -15,20 +15,22 @@ public enum TelemetryFailureCategory public sealed class TelemetryAggregation { - internal const int SchemaVersion = 2; + internal const int SchemaVersion = 3; - public TelemetryAggregation(string operation, TelemetryFailureCategory failureCategory, string result, long count = 1) + public TelemetryAggregation(string operation, TelemetryFailureCategory failureCategory, string result, long count = 1, string previousState = null) { ArgumentOutOfRangeException.ThrowIfNegativeOrZero(count); this.Operation = operation; this.FailureCategory = failureCategory; this.Result = result; this.Count = count; + this.PreviousState = previousState; } public string Operation { get; } public TelemetryFailureCategory FailureCategory { get; } public string Result { get; } public long Count { get; } + public string PreviousState { get; } } } diff --git a/GVFS/GVFS.Common/Tracing/TelemetryAggregator.cs b/GVFS/GVFS.Common/Tracing/TelemetryAggregator.cs index 693d3e75e3..307822e0f9 100644 --- a/GVFS/GVFS.Common/Tracing/TelemetryAggregator.cs +++ b/GVFS/GVFS.Common/Tracing/TelemetryAggregator.cs @@ -6,11 +6,12 @@ namespace GVFS.Common.Tracing internal sealed class TelemetryAggregator { internal const int Capacity = 64; + internal const string SummaryEventName = "TelemetrySummary"; private static readonly TimeSpan Interval = TimeSpan.FromSeconds(60); private readonly object gate = new object(); private readonly TimeProvider timeProvider; - private readonly Dictionary<(string EventName, string Operation, string Category, string Result), Counter> counters = new Dictionary<(string, string, string, string), Counter>(); + private readonly Dictionary<(string EventName, string Operation, string Category, string Result, string PreviousState), Counter> counters = new Dictionary<(string, string, string, string, string), Counter>(); private Counter overflow; private long intervalStarted; @@ -36,7 +37,7 @@ public void Record(TraceEventMessage message, Action emit) TelemetryAggregation aggregation = message.TelemetryAggregation; if (aggregation != null) { - (string, string, string, string) key = (message.EventName, aggregation.Operation, aggregation.FailureCategory.ToString(), aggregation.Result); + (string, string, string, string, string) key = (message.EventName, aggregation.Operation, aggregation.FailureCategory.ToString(), aggregation.Result, aggregation.PreviousState); if (!this.counters.TryGetValue(key, out Counter counter)) { if (this.counters.Count < Capacity) @@ -46,13 +47,14 @@ public void Record(TraceEventMessage message, Action emit) } else { - this.overflow = this.overflow ?? new Counter(("Overflow", "Overflow", "Overflow", "Overflow"), now); + this.overflow = this.overflow ?? new Counter(("Overflow", "Overflow", "Overflow", "Overflow", null), now); counter = this.overflow; } } sample = counter.ObservedCount == 0 && counter != this.overflow; counter.ObservedCount += aggregation.Count; + counter.LastObservedAtUtc = now; if (sample) { ++counter.SampleCount; @@ -100,11 +102,17 @@ private static void EmitSummaries(List completed, DateTime now, Action< { "SuppressedCount", counter.ObservedCount - counter.SampleCount }, { "IntervalStartUtc", counter.StartedAtUtc.ToString("O") }, { "IntervalEndUtc", now.ToString("O") }, + { "LastObservedAtUtc", counter.LastObservedAtUtc.ToString("O") }, { "OverflowCount", counter.Key.EventName == "Overflow" ? counter.ObservedCount : 0L }, }; + if (counter.Key.PreviousState != null) + { + metadata.Add("PreviousState", counter.Key.PreviousState); + } + emit(new TraceEventMessage { - EventName = "TelemetrySummary", + EventName = SummaryEventName, Level = EventLevel.Informational, Keywords = Keywords.Telemetry, Opcode = EventOpcode.Info, @@ -129,16 +137,18 @@ private List Drain() private sealed class Counter { - public Counter((string EventName, string Operation, string Category, string Result) key, DateTime startedAtUtc) + public Counter((string EventName, string Operation, string Category, string Result, string PreviousState) key, DateTime startedAtUtc) { this.Key = key; this.StartedAtUtc = startedAtUtc; + this.LastObservedAtUtc = startedAtUtc; } - public (string EventName, string Operation, string Category, string Result) Key { get; } + public (string EventName, string Operation, string Category, string Result, string PreviousState) Key { get; } public DateTime StartedAtUtc { get; } public long ObservedCount { get; set; } public long SampleCount { get; set; } + public DateTime LastObservedAtUtc { get; set; } } } } diff --git a/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs b/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs index 7c8a6a18b0..b2b7f112e5 100644 --- a/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs +++ b/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs @@ -151,7 +151,7 @@ private string CreatePipeMessage(TraceEventMessage message) { EnlistmentId = this.enlistmentId, MountId = this.mountId, - GitCommandSessionId = this.GitCommandSessionId, + GitCommandSessionId = message.EventName == TelemetryAggregator.SummaryEventName ? null : this.GitCommandSessionId, Json = message.Payload }, @@ -195,6 +195,7 @@ public class PipeMessagePayload [JsonPropertyName("mountId")] public string MountId { get; set; } [JsonPropertyName("gitCommandSessionId")] + [JsonIgnore(Condition = JsonIgnoreCondition.WhenWritingNull)] public string GitCommandSessionId { get; set; } [JsonPropertyName("json")] public string Json { get; set; } diff --git a/GVFS/GVFS.UnitTests/Tracing/TelemetryAggregatorTests.cs b/GVFS/GVFS.UnitTests/Tracing/TelemetryAggregatorTests.cs index 40853c9399..e9b81165c7 100644 --- a/GVFS/GVFS.UnitTests/Tracing/TelemetryAggregatorTests.cs +++ b/GVFS/GVFS.UnitTests/Tracing/TelemetryAggregatorTests.cs @@ -40,10 +40,12 @@ public void StormRetainsOneSampleAndExactIntervalCounters() Assert.That(root.GetProperty("IntervalEndUtc").GetDateTime(), Is.EqualTo(clock.UtcStart.AddSeconds(65).UtcDateTime)); Assert.That(root.TryGetProperty("RequestId", out _), Is.False); Assert.That(root.GetProperty("OriginalEventName").GetString(), Is.EqualTo("NetworkError")); - Assert.That(root.GetProperty("TelemetrySchemaVersion").GetInt32(), Is.EqualTo(2)); + Assert.That(root.GetProperty("TelemetrySchemaVersion").GetInt32(), Is.EqualTo(3)); Assert.That(root.GetProperty("TelemetryAggregation").GetString(), Is.EqualTo("Summary")); Assert.That(root.GetProperty("AggregationResult").GetString(), Is.EqualTo("Rejected")); Assert.That(root.GetProperty("OverflowCount").GetInt64(), Is.Zero); + Assert.That(root.GetProperty("LastObservedAtUtc").GetDateTime(), Is.EqualTo(clock.UtcStart.AddSeconds(5).UtcDateTime)); + Assert.That(root.TryGetProperty("PreviousState", out _), Is.False); Assert.That(output[1].Level, Is.EqualTo(EventLevel.Informational)); Assert.That(output[1].Opcode, Is.EqualTo(EventOpcode.Info)); } diff --git a/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs b/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs index fdfcd39743..d1f38c6c4c 100644 --- a/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs +++ b/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs @@ -206,7 +206,7 @@ public async Task DisposalDeliversPendingSummaryAndPreservesLegacyResult() { Assert.That(payload.RootElement.GetProperty("result").GetString(), Is.EqualTo("0xC0000467")); Assert.That(payload.RootElement.GetProperty("AggregationResult").GetString(), Is.EqualTo("Failed")); - Assert.That(payload.RootElement.GetProperty("TelemetrySchemaVersion").GetInt32(), Is.EqualTo(2)); + Assert.That(payload.RootElement.GetProperty("TelemetrySchemaVersion").GetInt32(), Is.EqualTo(3)); Assert.That(payload.RootElement.GetProperty("TelemetryAggregation").GetString(), Is.EqualTo("Sample")); Assert.That(payload.RootElement.TryGetProperty("Result", out _), Is.False); } @@ -227,6 +227,136 @@ public async Task DisposalDeliversPendingSummaryAndPreservesLegacyResult() } } + [TestCase] + public async Task CrossCommandSummaryOmitsSessionButSamplesRetainIt() + { + string pipeName = "gvfs-telemetry-test-" + Guid.NewGuid().ToString("N"); + TelemetryAggregatorTests.TestClock clock = new TelemetryAggregatorTests.TestClock(); + using (CancellationTokenSource timeout = new CancellationTokenSource(TimeSpan.FromSeconds(15))) + using (NamedPipeServerStream server = CreateServer(pipeName)) + using (StreamReader reader = new StreamReader(server, Encoding.UTF8, false, 1024, leaveOpen: true)) + using (JsonTracer tracer = new JsonTracer("Microsoft-GVFS-Test", "Root", disableTelemetry: true)) + using (TelemetryDaemonEventListener remote = new TelemetryDaemonEventListener("Microsoft.Git.GVFS", "synthetic-enlistment", "synthetic-mount", pipeName, null, clock)) + { + tracer.AddEventListener(remote); + Task connection = server.WaitForConnectionAsync(timeout.Token); + tracer.SetGitCommandSessionId("session-A"); + TraceRejection(tracer); + await connection; + Assert.That((await ReadMessage(reader, timeout.Token)).Payload.GitCommandSessionId, Is.EqualTo("session-A")); + + tracer.SetGitCommandSessionId("session-B"); + TraceRejection(tracer); + tracer.SetGitCommandSessionId("session-C"); + clock.Advance(TimeSpan.FromSeconds(60)); + tracer.RelatedEvent(EventLevel.Informational, "HealthyEvent", null, Keywords.Telemetry); + string summaryJson = await reader.ReadLineAsync(timeout.Token); + using (JsonDocument envelope = JsonDocument.Parse(summaryJson)) + { + Assert.That(envelope.RootElement.GetProperty("payload").TryGetProperty("gitCommandSessionId", out _), Is.False); + } + + TelemetryDaemonEventListener.PipeMessage summary = TelemetryDaemonEventListener.PipeMessage.FromJson(summaryJson); + Assert.That(summary.EventName, Is.EqualTo("TelemetrySummary")); + Assert.That(summary.Payload.EnlistmentId, Is.EqualTo("synthetic-enlistment")); + Assert.That(summary.Payload.MountId, Is.EqualTo("synthetic-mount")); + using (JsonDocument payload = JsonDocument.Parse(summary.Payload.Json)) + { + Assert.That(payload.RootElement.GetProperty("ObservedCount").GetInt64(), Is.EqualTo(2)); + Assert.That(payload.RootElement.GetProperty("SampleCount").GetInt64(), Is.EqualTo(1)); + Assert.That(payload.RootElement.GetProperty("SuppressedCount").GetInt64(), Is.EqualTo(1)); + } + + TelemetryDaemonEventListener.PipeMessage healthy = await ReadMessage(reader, timeout.Token); + Assert.That(healthy.EventName, Is.EqualTo("HealthyEvent")); + Assert.That(healthy.Payload.GitCommandSessionId, Is.EqualTo("session-C")); + } + } + + [TestCase] + public async Task BreakerRecoverySampleSurvivesInitialAcceptingAndRepeatedTransitions() + { + RetryCircuitBreaker.Reset(); + try + { + string pipeName = "gvfs-telemetry-test-" + Guid.NewGuid().ToString("N"); + TelemetryAggregatorTests.TestClock clock = new TelemetryAggregatorTests.TestClock(); + using (CancellationTokenSource timeout = new CancellationTokenSource(TimeSpan.FromSeconds(15))) + using (NamedPipeServerStream server = CreateServer(pipeName)) + using (StreamReader reader = new StreamReader(server, Encoding.UTF8, false, 1024, leaveOpen: true)) + using (JsonTracer tracer = new JsonTracer("Microsoft-GVFS-Test", "Root", disableTelemetry: true)) + using (TelemetryDaemonEventListener remote = new TelemetryDaemonEventListener("Microsoft.Git.GVFS", "synthetic-enlistment", "synthetic-mount", pipeName, null, clock)) + { + tracer.AddEventListener(remote); + Task connection = server.WaitForConnectionAsync(timeout.Token); + RetryWrapper wrapper = new RetryWrapper(1, CancellationToken.None, tracer: tracer); + wrapper.Invoke(attempt => new RetryWrapper.CallbackResult(true)); + wrapper.Invoke(attempt => + { + RetryCircuitBreaker.Configure(1, 30000); + return new RetryWrapper.CallbackResult(new IOException("Synthetic failure"), shouldRetry: true); + }); + RetryCircuitBreaker.Configure(1, 0); + wrapper.Invoke(attempt => new RetryWrapper.CallbackResult(true)); + await connection; + + string[] previousStates = { "Unknown", "Accepting", "Rejecting", "CooldownElapsed" }; + string[] states = { "Accepting", "Rejecting", "CooldownElapsed", "Accepting" }; + for (int i = 0; i < states.Length; ++i) + { + TelemetryDaemonEventListener.PipeMessage sample = await ReadMessage(reader, timeout.Token); + Assert.That(sample.EventName, Is.EqualTo("RetryCircuitBreakerState")); + using (JsonDocument payload = JsonDocument.Parse(sample.Payload.Json)) + { + Assert.That(payload.RootElement.GetProperty("PreviousState").GetString(), Is.EqualTo(previousStates[i])); + Assert.That(payload.RootElement.GetProperty("State").GetString(), Is.EqualTo(states[i])); + Assert.That(payload.RootElement.GetProperty("AggregationResult").GetString(), Is.EqualTo(states[i])); + } + } + + clock.Advance(TimeSpan.FromSeconds(10)); + wrapper.Invoke(attempt => + { + RetryCircuitBreaker.Configure(1, 30000); + return new RetryWrapper.CallbackResult(new IOException("Synthetic failure"), shouldRetry: true); + }); + RetryCircuitBreaker.Configure(1, 0); + clock.Advance(TimeSpan.FromSeconds(2)); + wrapper.Invoke(attempt => + { + clock.Advance(TimeSpan.FromSeconds(1)); + return new RetryWrapper.CallbackResult(true); + }); + tracer.RelatedEvent(EventLevel.Informational, "RepeatedTransitionsComplete", null, Keywords.Telemetry); + Assert.That((await ReadMessage(reader, timeout.Token)).EventName, Is.EqualTo("RepeatedTransitionsComplete")); + + clock.Advance(TimeSpan.FromSeconds(60)); + tracer.RelatedEvent(EventLevel.Informational, "Flush", null, Keywords.Telemetry); + for (int i = 0; i < states.Length; ++i) + { + TelemetryDaemonEventListener.PipeMessage summary = await ReadMessage(reader, timeout.Token); + Assert.That(summary.EventName, Is.EqualTo("TelemetrySummary")); + using (JsonDocument payload = JsonDocument.Parse(summary.Payload.Json)) + { + Assert.That(payload.RootElement.GetProperty("PreviousState").GetString(), Is.EqualTo(previousStates[i])); + Assert.That(payload.RootElement.GetProperty("AggregationResult").GetString(), Is.EqualTo(states[i])); + Assert.That(payload.RootElement.GetProperty("ObservedCount").GetInt64(), Is.EqualTo(i == 0 ? 1 : 2)); + Assert.That(payload.RootElement.GetProperty("SampleCount").GetInt64(), Is.EqualTo(1)); + Assert.That(payload.RootElement.GetProperty("SuppressedCount").GetInt64(), Is.EqualTo(i == 0 ? 0 : 1)); + int[] lastSeconds = { 0, 10, 12, 13 }; + Assert.That(payload.RootElement.GetProperty("LastObservedAtUtc").GetDateTime(), Is.EqualTo(clock.UtcStart.AddSeconds(lastSeconds[i]).UtcDateTime)); + } + } + + Assert.That((await ReadMessage(reader, timeout.Token)).EventName, Is.EqualTo("Flush")); + } + } + finally + { + RetryCircuitBreaker.Reset(); + } + } + private static NamedPipeServerStream CreateServer(string pipeName) { return new NamedPipeServerStream(pipeName, PipeDirection.In, 1, PipeTransmissionMode.Byte, PipeOptions.Asynchronous);