Sanitizing stack traces to improve readability #1051

fabiocav · 2017-03-09T02:12:11Z

There are two goals with this PR:

Improve readability of exception messages/stack traces

This is particularly problematic for Azure Functions users. With this changes, we are sanitizing the exception stack trace prior to logging to:

Remove async state machine frames (this causes a significant amount of noise)
Convert the compiler generated state machine code to the appropriate async method name and marking it with async
Show async method arguments when possible
Properly formatting AggregateExceptions and the associated inner exceptions

Here's an example of the expected output with the same exception:
Before formatting:

System.AggregateException: One or more errors occurred. ---> System.Exception: Crash!
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.<CrashAsync>d__4.MoveNext() in D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs:line 117
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.<Run2Async>d__3.MoveNext() in D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs:line 111
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.<Run1Async>d__2.MoveNext() in D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs:line 106
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at System.Threading.Tasks.Task.Wait()
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.Run(String arg) in D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs:line 96
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.Run() in D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs:line 89
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.FormatException_RemovesAsyncFrames() in D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs:line 20
---> (Inner Exception #0) System.Exception: Crash!
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.<CrashAsync>d__4.MoveNext() in D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs:line 117
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.<Run2Async>d__3.MoveNext() in D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs:line 111
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.<Run1Async>d__2.MoveNext() in D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs:line 106<---

After formatting:

System.AggregateException : One or more errors occurred. ---> Crash!
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout,CancellationToken cancellationToken)
   at System.Threading.Tasks.Task.Wait()
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.Run(String arg) at D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs : 96
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.Run() at D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs : 89
   at Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.FormatException_RemovesAsyncFrames() at D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs : 20
---> (Inner Exception #0) System.Exception : Crash!
   at async Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.CrashAsync() at D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs : 117
   at async Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.Run2Async() at D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs : 111
   at async Microsoft.Azure.WebJobs.Host.UnitTests.ExceptionFormatterTests.TestClass.Run1Async() at D:\src\gh.fabiocav\awj\azure-webjobs-sdk\test\Microsoft.Azure.WebJobs.Host.UnitTests\ExceptionFormatterTests.cs : 106<---

Avoid losing important stack information in logs

Changed the log truncation strategy to preserve the top of the stack as, in most customer cases, the top frames contain the relevant information and exception details. This issue is also mitigated by the change to sanitize messages as much less information is lost due to truncation.

fabiocav · 2017-03-09T02:13:06Z

src/Microsoft.Azure.WebJobs.Host/Executors/ExceptionExtensions.cs

@@ -1,70 +0,0 @@
-// Copyright (c) .NET Foundation. All rights reserved.
-// Licensed under the MIT License. See License.txt in the project root for license information.


Consolidated this into the other ExceptionExtensions in the Extensions folder.

fabiocav · 2017-03-09T02:14:03Z

src/Microsoft.Azure.WebJobs.Host/Extensions/ExceptionExtensions.cs

+
+            if (additionalDetails == null || additionalDetails.Count == 0)
+            {
+                return ExceptionFormatter.GetFormattedException(exception);


This now uses the GetFormattedException method as opposed to just calling ToString

fabiocav · 2017-03-09T02:14:09Z

src/Microsoft.Azure.WebJobs.Host/Extensions/ExceptionExtensions.cs

+            else
+            {
+                StringBuilder builder = new StringBuilder();
+                builder.AppendLine(ExceptionFormatter.GetFormattedException(exception));


fabiocav · 2017-03-09T02:15:16Z

src/Microsoft.Azure.WebJobs.Host/Loggers/FastTableLoggerProvider.cs

@@ -124,7 +124,7 @@ public Task SaveAndCloseAsync(FunctionInstanceLogEntry item, CancellationToken c
                    {                        
                        // 0123456789
                        // abcdefghij
-                        str = "..." + str.Substring(str.Length - (FunctionInstanceLogEntry.MaxLogOutputLength - 3));
+                        str = str.Substring(0, FunctionInstanceLogEntry.MaxLogOutputLength - 1) + "…";


Minor change, but moved from using ... to using …

mathewc · 2017-03-09T03:11:50Z

src/Microsoft.Azure.WebJobs.Host/Diagnostics/ExceptionFormatter.cs

+                return GetStackForAggregateException(exception, aggregate);
+            }
+
+            return GetStackForException(exception, includeMessageOnly: false);


In all the grovelling through stack frames, etc. accessing members, etc. I'm wondering if in strange cases (e.g. generated/emittd code, etc.) what the possibilities are for some info to not be there (e.g. null refs) causing things to blow up. Wondering if we shouldn't have a try/catch surrounding all this that defaults to the full stack trace if for some reason our sanitization logic blows up?

mathewc · 2017-03-09T03:22:16Z

test/Microsoft.Azure.WebJobs.Host.UnitTests/ExceptionFormatterTests.cs

+            {
+                string formattedException = ExceptionFormatter.GetFormattedException(exc);
+
+                Assert.False(Regex.Match(formattedException, "d__.\\.MoveNext()").Success);


it would help see what is actually going on if these tests tested a full string literal, so we can see the true formatting, and it would also help catch errors better. I realize though that line numbers might change over time, making this hard. Perhaps if the test class were in its own file, so line numbers don't jump around often? or perhaps if a regex is used to match any line numbers?

Have some additional tests validating against literal strings for expected traces.

mathewc · 2017-03-09T03:23:25Z

test/Microsoft.Azure.WebJobs.Host.UnitTests/ExceptionFormatterTests.cs

+            {
+                if (string.Equals(arg, "Test1"))
+                {
+                    Run1Async().Wait();


Should we have some non async tests too?

mamaso · 2017-03-09T19:56:48Z

Massive improvement, great work!

dsyme · 2017-03-10T16:35:59Z

@fabiocav Nice work! Does it applies to F# too? Might be good to add a smoke test for that?

dnfclas added the cla-already-signed label Mar 9, 2017

fabiocav added the in progress label Mar 9, 2017

fabiocav commented Mar 9, 2017

View reviewed changes

fabiocav requested review from mathewc, brettsam and MikeStall March 9, 2017 02:16

mathewc reviewed Mar 9, 2017

View reviewed changes

Sanitizing stack traces to improve readability

7117d9d

fabiocav force-pushed the excformat branch from 259923e to 7117d9d Compare March 9, 2017 19:27

fabiocav merged commit 7117d9d into Azure:dev Mar 9, 2017

fabiocav removed the in progress label Mar 9, 2017

fabiocav deleted the excformat branch March 9, 2017 19:30

fabiocav mentioned this pull request Mar 9, 2017

Errors unreadable when Exceptions thrown Azure/azure-functions-host#1235

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Sanitizing stack traces to improve readability #1051

Sanitizing stack traces to improve readability #1051

fabiocav commented Mar 9, 2017 •

edited

fabiocav Mar 9, 2017

fabiocav Mar 9, 2017

fabiocav Mar 9, 2017

fabiocav Mar 9, 2017

mathewc Mar 9, 2017 •

edited

fabiocav Mar 9, 2017

mathewc Mar 9, 2017

fabiocav Mar 9, 2017

mathewc Mar 9, 2017

fabiocav Mar 9, 2017

mamaso commented Mar 9, 2017

dsyme commented Mar 10, 2017

		@@ -1,70 +0,0 @@
		// Copyright (c) .NET Foundation. All rights reserved.
		// Licensed under the MIT License. See License.txt in the project root for license information.

Sanitizing stack traces to improve readability #1051

Sanitizing stack traces to improve readability #1051

Conversation

fabiocav commented Mar 9, 2017 • edited

Improve readability of exception messages/stack traces

Avoid losing important stack information in logs

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mathewc Mar 9, 2017 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mamaso commented Mar 9, 2017

dsyme commented Mar 10, 2017

fabiocav commented Mar 9, 2017 •

edited

mathewc Mar 9, 2017 •

edited