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 5970469fd0..7a4fb4232e 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; } @@ -385,7 +405,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 26f4c3d298..a308e932c1 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..a2957d5b94 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,45 @@ 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" }; + string previousStateName = previousState < 0 ? "Unknown" : states[previousState]; + EventMetadata metadata = new EventMetadata + { + { "PreviousState", previousStateName }, + { "State", states[state] }, + { "Trigger", trigger }, + { "ObservedAtUtc", observedAtUtc.ToString("O") }, + }; + metadata.SetTelemetryAggregation(nameof(RetryCircuitBreaker), TelemetryFailureCategory.BreakerState, states[state], previousState: previousStateName); + tracer.RelatedEvent(EventLevel.Informational, "RetryCircuitBreakerState", metadata, Keywords.Telemetry); + } + /// /// Resets the circuit breaker to its initial state. Intended for testing. /// @@ -58,6 +99,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..0819aaa514 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, string previousState = null) + { + this.TelemetryAggregation = new TelemetryAggregation(operation, failureCategory, result, count, previousState); + 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..0e89f3c6c0 --- /dev/null +++ b/GVFS/GVFS.Common/Tracing/TelemetryAggregation.cs @@ -0,0 +1,36 @@ +using System; + +namespace GVFS.Common.Tracing +{ + public enum TelemetryFailureCategory + { + CircuitBreakerOpen, + NetworkUnavailable, + SizesUnavailable, + MissingObjectSize, + None, + EvictionUnavailable, + BreakerState, + } + + public sealed class TelemetryAggregation + { + internal const int SchemaVersion = 3; + + 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 new file mode 100644 index 0000000000..307822e0f9 --- /dev/null +++ b/GVFS/GVFS.Common/Tracing/TelemetryAggregator.cs @@ -0,0 +1,154 @@ +using System; +using System.Collections.Generic; + +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, string PreviousState), Counter> counters = new Dictionary<(string, 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, 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) + { + counter = new Counter(key, now); + this.counters.Add(key, counter); + } + else + { + 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; + } + } + } + + 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") }, + { "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 = SummaryEventName, + 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, string PreviousState) key, DateTime startedAtUtc) + { + this.Key = key; + this.StartedAtUtc = startedAtUtc; + this.LastObservedAtUtc = startedAtUtc; + } + + 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 b293898104..b2b7f112e5 100644 --- a/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs +++ b/GVFS/GVFS.Common/Tracing/TelemetryDaemonEventListener.cs @@ -13,6 +13,7 @@ public class TelemetryDaemonEventListener : EventListener, IQueuedPipeStringWrit private readonly string mountId; private readonly string vfsVersion; private readonly string vfsArchitecture; + private readonly TelemetryAggregator aggregator; private QueuedPipeStringWriter pipeWriter; @@ -21,7 +22,8 @@ internal TelemetryDaemonEventListener( 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 @@ internal 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); @@ -142,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 }, @@ -186,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.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 1e0c60aaa5..efc84f1781 100644 --- a/GVFS/GVFS.Hooks/GVFS.Hooks.csproj +++ b/GVFS/GVFS.Hooks/GVFS.Hooks.csproj @@ -89,6 +89,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 7a654b5c60..069189a12b 100644 --- a/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs @@ -54,6 +54,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() @@ -199,6 +233,7 @@ public void TerminalBlobHydrationFailureRecordsHttpStatusCode() terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"DownloadFailed\""); terminalError.ShouldContain("\"HttpStatusCode\":401"); terminalError.ShouldContain("\"HttpStatusName\":\"Unauthorized\""); + terminalError.ShouldNotContain(false, "TelemetryAggregation"); } [TestCase] @@ -237,6 +272,7 @@ public void TerminalBlobHydrationFailureRecordsTransientHttpStatusCode() terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"DownloadFailed\""); terminalError.ShouldContain("\"HttpStatusCode\":503"); terminalError.ShouldContain("\"HttpStatusName\":\"ServiceUnavailable\""); + terminalError.ShouldNotContain(false, "TelemetryAggregation"); } [TestCase] @@ -381,17 +417,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] @@ -1268,6 +1318,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; } @@ -1306,6 +1357,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 @@ -1377,6 +1433,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 0f3ed2c503..dc7426ceba 100644 --- a/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs @@ -33,6 +33,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 f1d284a54b..e9feca9054 100644 --- a/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs +++ b/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs @@ -35,6 +35,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..e9b81165c7 --- /dev/null +++ b/GVFS/GVFS.UnitTests/Tracing/TelemetryAggregatorTests.cs @@ -0,0 +1,197 @@ +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(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)); + } + + 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 3c9ced2ac8..d1f38c6c4c 100644 --- a/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs +++ b/GVFS/GVFS.UnitTests/Tracing/TelemetryDaemonEventListenerTests.cs @@ -8,8 +8,10 @@ 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.CommandLine; using GVFS.Common.FileSystem; using GVFS.Common.NamedPipes; @@ -117,6 +119,280 @@ private static async Task ReadTelemetryAsync(NamedPipeServerStream serve } } + [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(3)); + 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(); + } + } + + [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); + } + + 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); }