Merged PR 674879: Exclude non essential methods from exception's stack trace

This PR updates `Ben.Demystifier` logic that is embeded into `BuildXL.Utilities` to support the latest language changes.

The PR also adds support for respecting `StackTraceHiddenAttribute` for async methods and adds tests to check that the methods marked with `StackTraceHiddenAttribute` are not part of the error output.

Related work items: #1979115

Author: SergeyTeplyakov

Public/Src/Cache/ContentStore/Distributed/NuCache/EventStreaming/EventHubContentLocationEventStore.cs

@@ -18,6 +18,7 @@
 using BuildXL.Cache.ContentStore.Tracing.Internal;
 using BuildXL.Cache.ContentStore.Utils;
 using BuildXL.Native.IO;
+using BuildXL.Utilities;
 using BuildXL.Utilities.ParallelAlgorithms;
 using BuildXL.Utilities.Tasks;
 using BuildXL.Utilities.Tracing;
@@ -207,7 +208,7 @@ await _extraEventHubClientRetryPolicy.ExecuteAsync(async () =>
                         // If the error is not retryable, then the entire operation will fail and we don't need to double trace the error.
                         if (TransientEventHubErrorDetectionStrategy.IsRetryable(e))
                         {
-                            Tracer.Debug(context, $"{Tracer.Name}.{nameof(SendEventsCoreAsync)} failed with retryable error=[{e}]");
+                            Tracer.Debug(context, $"{Tracer.Name}.{nameof(SendEventsCoreAsync)} failed with retryable error=[{e.ToStringDemystified()}]");
                         }
 
                         throw;

Public/Src/Cache/ContentStore/Library/Stores/FileSystemContentStoreInternalChecker.cs

@@ -366,7 +366,7 @@ void traceProgressIfNeeded(ContentHash currentHash, int currentHashIndex)
             }
             catch (Exception e)
             {
-                _tracer.Warning(context, $"SelfCheck: Content hash is invalid. Hash={expectedHash.ToShortString()}, Error={e}");
+                _tracer.Warning(context, $"SelfCheck: Content hash is invalid. Hash={expectedHash.ToShortString()}, Error={e.DemystifyToString()}");
 
                 return (isValid: true, error: string.Empty);
             }

Public/Src/Cache/ContentStore/Library/Tracing/OperationContextExtensions.cs

@@ -2,6 +2,7 @@
 // Licensed under the MIT License.
 
 using System;
+using System.Diagnostics;
 using System.Runtime.CompilerServices;
 using System.Threading;
 using System.Threading.Tasks;
@@ -260,6 +261,7 @@ protected void TracePendingOperation(StopwatchSlim stopwatch)
         }
 
         /// <nodoc />
+        [StackTraceHidden]
         protected T RunOperationAndConvertExceptionToError<T>(Func<T> operation)
             where T : ResultBase
         {
@@ -276,6 +278,7 @@ protected T RunOperationAndConvertExceptionToError<T>(Func<T> operation)
         }
 
         /// <nodoc />
+        [StackTraceHidden]
         protected async Task<T> RunOperationAndConvertExceptionToErrorAsync<T>(Func<Task<T>> operation, StopwatchSlim stopwatch)
             where T : ResultBase
         {
@@ -347,6 +350,7 @@ public PerformAsyncOperationNonResultBuilder(OperationContext context, Tracer tr
         }
 
         /// <nodoc />
+        [StackTraceHidden]
         public async Task<TResult> RunAsync([CallerMemberName] string? caller = null)
         {
             // If the caller was not set by 'WithOptions' call, setting it here.
@@ -429,6 +433,7 @@ public PerformAsyncOperationBuilder(OperationContext context, Tracer tracer, Fun
         }
 
         /// <nodoc />
+        [StackTraceHidden]
         public virtual async Task<TResult> RunAsync([CallerMemberName] string? caller = null)
         {
             // If the caller was not set by 'WithOptions' call, setting it here.
@@ -470,13 +475,15 @@ public PerformAsyncOperationWithTimeoutBuilder(OperationContext context, Tracer
         }
 
         /// <nodoc />
+        [StackTraceHidden]
         public PerformAsyncOperationWithTimeoutBuilder<TResult> WithTimeout(TimeSpan? timeout)
         {
             _timeout = timeout;
             return this;
         }
 
         /// <nodoc />
+        [StackTraceHidden]
         public virtual async Task<TResult> RunAsync([CallerMemberName] string? caller = null)
         {
             // If the caller was not set by 'WithOptions' call, setting it here.
@@ -496,6 +503,7 @@ public virtual async Task<TResult> RunAsync([CallerMemberName] string? caller =
         }
 
         /// <nodoc />
+        [StackTraceHidden]
         protected async Task<T> RunOperationAndConvertExceptionToErrorAsync<T>(Func<OperationContext, Task<T>> operation, StopwatchSlim stopwatch)
             where T : ResultBase
         {
@@ -515,6 +523,7 @@ protected async Task<T> RunOperationAndConvertExceptionToErrorAsync<T>(Func<Oper
         }
 
         /// <nodoc />
+        [StackTraceHidden]
         public static async Task<T> WithOptionalTimeoutAsync<T>(Func<OperationContext, Task<T>> operation, TimeSpan? timeout, OperationContext context, [CallerMemberName] string? caller = null) where T : ResultBase
         {
             if (timeout == null || timeout.Value == TimeSpan.MaxValue)

Public/Src/Cache/ContentStore/Library/Utils/BandwidthChecker.cs

@@ -163,7 +163,7 @@ void traceCopyTaskFailures()
                         {
                             if (!(t.Exception?.InnerException is ObjectDisposedException))
                             {
-                                context.TracingContext.Debug($"Checked copy failed. {t.Exception}", component: nameof(BandwidthChecker), operation: nameof(CheckBandwidthAtIntervalAsync));
+                                context.TracingContext.Debug($"Checked copy failed. {t.Exception?.DemystifyToString()}", component: nameof(BandwidthChecker), operation: nameof(CheckBandwidthAtIntervalAsync));
                             }
                         }
                     });

Public/Src/Cache/ContentStore/Test/Tracing/PerformOperationTests.cs

@@ -25,12 +25,9 @@ namespace BuildXL.Cache.ContentStore.Test.Tracing
 {
     public class PerformOperationTests : TestWithOutput
     {
-        private readonly ITestOutputHelper _testOutputHelper;
-
-        public PerformOperationTests(ITestOutputHelper output, ITestOutputHelper testOutputHelper)
+        public PerformOperationTests(ITestOutputHelper output)
         : base(output)
         {
-            _testOutputHelper = testOutputHelper;
         }
 
         public enum AsyncOperationKind
@@ -146,6 +143,61 @@ Exception exceptionWithStackTrace()
 
             // The final result should contain an original method that threw the error.
             finalErrorResult.Should().Contain("nested");
+            finalErrorResult.Should().NotContain(nameof(Interfaces.Results.ResultsExtensions.ThrowIfFailure));
+
+            // Both the full string and the error message should have the original error message
+            finalErrorResult.Should().Contain(errorMessage);
+            r3.ErrorMessage.Should().Contain(errorMessage);
+
+            // The error message should not be repeated multiple times.
+            finalErrorResult.Split(new string[] { errorMessage }, StringSplitOptions.RemoveEmptyEntries).Length.Should().Be(2);
+        }
+
+        [Fact]
+        public async Task TestResultPropagationExceptionInAsyncMethod()
+        {
+            const string errorMessage = "Invalid operation error";
+            var tracer = new Tracer("MyTracer");
+            var context = new OperationContext(new Context(TestGlobal.Logger));
+
+            var r1 = context.PerformOperationAsync(
+                tracer,
+                () =>
+                {
+                    new BoolResult(exceptionWithStackTrace()).ThrowIfFailure();
+                    return BoolResult.SuccessTask;
+
+                    Exception exceptionWithStackTrace()
+                    {
+                        try
+                        {
+                            nested();
+                            throw new InvalidOperationException("Should not get here!");
+                        }
+                        catch (Exception e)
+                        {
+                            return e;
+                        }
+                    }
+
+                    void nested() => throw new InvalidOperationException(errorMessage);
+                });
+
+            var r3 = await context.PerformOperationAsync(
+                tracer,
+                async () =>
+                {
+                    await r1.ThrowIfFailureAsync();
+                    return BoolResult.Success;
+                }, extraStartMessage: "Final operation");
+
+            var finalErrorResult = r3.ToString();
+
+            Output.WriteLine("R1: " + (await r1));
+
+            // The final result should contain an original method that threw the error.
+            finalErrorResult.Should().Contain("nested");
+            finalErrorResult.Should().NotContain(nameof(Interfaces.Results.ResultsExtensions.ThrowIfFailureAsync));
 
             // Both the full string and the error message should have the original error message
             finalErrorResult.Should().Contain(errorMessage);

Public/Src/Utilities/Utilities/Ben.Demystifier/EnhancedStackFrame.cs

@@ -1,24 +1,30 @@
-// Copyright (c) Microsoft Corporation.
-// Licensed under the MIT License.
+// Copyright (c) Ben A Adams. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System.Reflection;
 
+#nullable enable
+
 namespace System.Diagnostics
 {
     /// <nodoc />
-    public class EnhancedStackFrame : StackFrame
+    internal class EnhancedStackFrame : StackFrame
     {
-        private readonly string _fileName;
+        private readonly string? _fileName;
         private readonly int _lineNumber;
         private readonly int _colNumber;
 
-        /// <nodoc />
         public StackFrame StackFrame { get; }
 
-        /// <nodoc />
+        public bool IsRecursive
+        {
+            get => MethodInfo.RecurseCount > 0;
+            internal set => MethodInfo.RecurseCount++;
+        }
+
         public ResolvedMethod MethodInfo { get; }
 
-        internal EnhancedStackFrame(StackFrame stackFrame, ResolvedMethod methodInfo, string fileName, int lineNumber, int colNumber)
+        internal EnhancedStackFrame(StackFrame stackFrame, ResolvedMethod methodInfo, string? fileName, int lineNumber, int colNumber)
             : base(fileName, lineNumber, colNumber)
         {
             StackFrame = stackFrame;
@@ -29,6 +35,14 @@ internal EnhancedStackFrame(StackFrame stackFrame, ResolvedMethod methodInfo, st
             _colNumber = colNumber;
         }
 
+        internal bool IsEquivalent(ResolvedMethod methodInfo, string? fileName, int lineNumber, int colNumber)
+        {
+            return _lineNumber == lineNumber &&
+                _colNumber == colNumber &&
+                _fileName == fileName &&
+                MethodInfo.IsSequentialEquivalent(methodInfo);
+        }
+
         /// <summary>
         ///      Gets the column number in the file that contains the code that is executing. 
         ///      This information is typically extracted from the debugging symbols for the executable.
@@ -48,7 +62,7 @@ internal EnhancedStackFrame(StackFrame stackFrame, ResolvedMethod methodInfo, st
         ///     This information is typically extracted from the debugging symbols for the executable.
         /// </summary>
         /// <returns>The file name, or null if the file name cannot be determined.</returns>
-        public override string GetFileName() => _fileName;
+        public override string? GetFileName() => _fileName;
 
         /// <summary>
         ///    Gets the offset from the start of the Microsoft intermediate language (MSIL)
@@ -63,7 +77,7 @@ internal EnhancedStackFrame(StackFrame stackFrame, ResolvedMethod methodInfo, st
         ///     Gets the method in which the frame is executing.
         /// </summary>
         /// <returns>The method in which the frame is executing.</returns>
-        public override MethodBase GetMethod() => StackFrame.GetMethod();
+        public override MethodBase? GetMethod() => StackFrame.GetMethod();
 
         /// <summary>
         ///     Gets the offset from the start of the native just-in-time (JIT)-compiled code