New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Make stack traces readable #24627

Closed
davkean opened this Issue Oct 13, 2017 · 21 comments

Comments

Projects
None yet
@davkean
Copy link
Member

davkean commented Oct 13, 2017

Now that Task, async and await are prevalent - stack traces have become a lot less readable.

Here's one that I was sent today:

System.InvalidOperationException: The specified API "ConditionedProperties" is not available because ProjectLoadSettings.DoNotEvaluateElementsWithFalseCondition was set when loading this project.
   at Microsoft.Build.Shared.ErrorUtilities.ThrowInvalidOperation(String resourceName, Object[] args) in e:\projects\msbuild_3\src\Shared\ErrorUtilities.cs:line 304
   at Microsoft.Build.Evaluation.Project.get_ConditionedProperties() in e:\projects\msbuild_3\src\Build\Definition\Project.cs:line 709
   at Microsoft.VisualStudio.ProjectSystem.CoreProjectConfigurationsDimensionsProvider.<GetProjectConfigurationDimensionsAsync>d__7.MoveNext()
--- 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 Microsoft.VisualStudio.ProjectSystem.DeclaredDimensionsProjectConfigurationsService.<CalculateKnownProjectConfigurationsAsync>d__9.MoveNext()
--- 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 Microsoft.VisualStudio.ProjectSystem.UnconfiguredProjectCache`1.<GetValueAsync>d__6.MoveNext()
--- 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 Microsoft.VisualStudio.ProjectSystem.ProjectConfigurationsServiceBase.<GetKnownProjectConfigurationsAsync>d__55.MoveNext()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at Microsoft.VisualStudio.ProjectSystem.VS.Tree.Dependencies.CrossTarget.CrossTargetSubscriptionHostBase.<UpdateProjectContextAsync>d__24.MoveNext()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.VisualStudio.ProjectSystem.DefaultingProjectConfigurationsServiceBase.<GetProjectConfigurationAsync>d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
--- 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.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.VisualStudio.ProjectSystem.VS.Tree.Dependencies.CrossTarget.CrossTargetSubscriptionHostBase.<UpdateProjectContextAndSubscriptionsAsync>d__23.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.VS.Implementation.VSUnconfiguredProjectIntegrationService.<GetActiveProjectConfigurationAsync>d__68.MoveNext()
--- 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.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.VisualStudio.ProjectSystem.VS.Implementation.VSUnconfiguredProjectIntegrationService.<RefreshActiveProjectConfigurationAsync>d__62.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.VS.Tree.Dependencies.CrossTarget.CrossTargetSubscriptionHostBase.<InitializeCoreAsync>d__20.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
--- 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 Microsoft.VisualStudio.ProjectSystem.VS.NuGet.NuGetRestorer.<RefreshActiveConfigurationAsync>d__18.MoveNext()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.VisualStudio.ProjectSystem.VS.Tree.Dependencies.Subscriptions.DependencySubscriptionsHost.<InitializeCoreAsync>d__45.MoveNext()
--- 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 Microsoft.VisualStudio.ProjectSystem.OnceInitializedOnceDisposedAsync.<<-ctor>b__4_0>d.MoveNext()
--- 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 Microsoft.VisualStudio.Threading.AsyncLazy`1.<>c__DisplayClass13_1.<<GetValueAsync>b__0>d.MoveNext()
--- 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 Microsoft.VisualStudio.ProjectSystem.VS.Tree.Dependencies.CrossTarget.CrossTargetSubscriptionHostBase.<EnsureInitialized>d__19.MoveNext()

Here it is minus the noise:

System.InvalidOperationException: The specified API "ConditionedProperties" is not available because ProjectLoadSettings.DoNotEvaluateElementsWithFalseCondition was set when loading this project.
   at Microsoft.Build.Shared.ErrorUtilities.ThrowInvalidOperation(String resourceName, Object[] args) in e:\projects\msbuild_3\src\Shared\ErrorUtilities.cs:line 304
   at Microsoft.Build.Evaluation.Project.get_ConditionedProperties() in e:\projects\msbuild_3\src\Build\Definition\Project.cs:line 709
   at Microsoft.VisualStudio.ProjectSystem.CoreProjectConfigurationsDimensionsProvider.<GetProjectConfigurationDimensionsAsync>d__7.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.DeclaredDimensionsProjectConfigurationsService.<CalculateKnownProjectConfigurationsAsync>d__9.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.UnconfiguredProjectCache`1.<GetValueAsync>d__6.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.ProjectConfigurationsServiceBase.<GetKnownProjectConfigurationsAsync>d__55.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.VS.Tree.Dependencies.CrossTarget.CrossTargetSubscriptionHostBase.<UpdateProjectContextAsync>d__24.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.DefaultingProjectConfigurationsServiceBase.<GetProjectConfigurationAsync>d__3.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.VS.Tree.Dependencies.CrossTarget.CrossTargetSubscriptionHostBase.<UpdateProjectContextAndSubscriptionsAsync>d__23.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.VS.Implementation.VSUnconfiguredProjectIntegrationService.<GetActiveProjectConfigurationAsync>d__68.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.VS.Implementation.VSUnconfiguredProjectIntegrationService.<RefreshActiveProjectConfigurationAsync>d__62.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.VS.Tree.Dependencies.CrossTarget.CrossTargetSubscriptionHostBase.<InitializeCoreAsync>d__20.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.VS.NuGet.NuGetRestorer.<RefreshActiveConfigurationAsync>d__18.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.VS.Tree.Dependencies.Subscriptions.DependencySubscriptionsHost.<InitializeCoreAsync>d__45.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.OnceInitializedOnceDisposedAsync.<<-ctor>b__4_0>d.MoveNext()
   at Microsoft.VisualStudio.Threading.AsyncLazy`1.<>c__DisplayClass13_1.<<GetValueAsync>b__0>d.MoveNext()
   at Microsoft.VisualStudio.ProjectSystem.VS.Tree.Dependencies.CrossTarget.CrossTargetSubscriptionHostBase.<EnsureInitialized>d__19.MoveNext()

Much more understandable/readable.

Is there something we can do to collapse/reduce the noise here?

@NickCraver

This comment has been minimized.

Copy link
Member

NickCraver commented Oct 13, 2017

We've got the same issue, not ideal (since this should be done on generation ideally), but we handle text-based versions after the fact like this:

dgtzm5wumaeokdx-1
dgtzyfau0aa44ws

Current code (again, string-based, but gives an idea): https://github.com/NickCraver/StackExchange.Exceptional/blob/master/src/StackExchange.Exceptional.Shared/ExceptionalUtils.StackTrace.cs

I'd love to see the framework do this much better. It's one of the big negatives to taking a codebase async.

@stephentoub

This comment has been minimized.

Copy link
Member

stephentoub commented Oct 13, 2017

@roryprimrose

This comment has been minimized.

Copy link

roryprimrose commented Oct 13, 2017

Yep, totally agree. I use https://github.com/aelij/AsyncFriendlyStackTrace to clean up the stack traces when logging them.

@aelij

This comment has been minimized.

Copy link
Contributor

aelij commented Oct 13, 2017

@karelz

This comment has been minimized.

Copy link
Member

karelz commented Oct 13, 2017

Closing as duplicate of #1370
(if you think it is not a dupe, please let me know and we can reopen)

@karelz karelz closed this Oct 13, 2017

@NickCraver

This comment has been minimized.

Copy link
Member

NickCraver commented Oct 13, 2017

Aren't these different issues? #1370 is talking about APIs, this is literally what the .ToSting() outputs, which may be a consumer of said API or may not use it at all.

@davkean davkean reopened this Oct 13, 2017

@davkean

This comment has been minimized.

Copy link
Member Author

davkean commented Oct 13, 2017

Yep, these are two different issues.

@karelz

This comment has been minimized.

Copy link
Member

karelz commented Oct 14, 2017

It was not clear to me from the above description that you're asking for a change in Exception.StackTrace and/or in Exception.ToString().
That may have interesting AppCompat impact + difference between platforms. OTOH it would be very nice and sane default vs. the full 'unreadable' stack today.

Ultimately, we will IMO solve both issues together - they have the same solution. Either way we will need a new API (either providing the full call stack, or the sane call stack). The only question is, if the default StackTrace and ToString() return the sane call stack or the full call stack.
So I would still suggest to close it as dupe, but I won't fight over it ;) ...

@davkean

This comment has been minimized.

Copy link
Member Author

davkean commented Oct 14, 2017

We could fix Exception.StackTrace without providing an API or provide an API without fixing Exception.StackTrace. Hence why I see them as separate.

@noahfalk

This comment has been minimized.

Copy link
Member

noahfalk commented Oct 14, 2017

@davidfowl can correct me if I'm wrong but I don't think the mentions of an API in #1370 were meant to be a fundamental requirement. He wanted better stack trace text, and then he speculated that a new API is how he would get it. If there is a way he gets better text without a new API I bet he is still happy.

@benaadams

This comment has been minimized.

Copy link
Collaborator

benaadams commented Oct 18, 2017

Had a go at changing the StackTrace by changing the stack :)

Has some outstanding issues/questions though dotnet/coreclr#14564

@danmosemsft

This comment has been minimized.

Copy link
Member

danmosemsft commented Nov 21, 2017

@benaadams after your various CoreCLR changes including the nice dotnet/coreclr#14655 what if anything remains to improve the original example stack in this issue?

@benaadams

This comment has been minimized.

Copy link
Collaborator

benaadams commented Jan 18, 2018

@danmosemsft with now merged
dotnet/coreclr#14652 "Hide post exception stack frames"
dotnet/coreclr#15781 "Remove Edi boundary for async"

if/when dotnet/coreclr#14655 "Resolve iterators and async methods in stacktrace" is merged (seems to have C# compiler approval? dotnet/coreclr#14655 (comment)) this will be resolved

@danmosemsft

This comment has been minimized.

Copy link
Member

danmosemsft commented Jan 18, 2018

Great!

karelz added a commit to dotnet/coreclr that referenced this issue Jan 25, 2018

Resolve iterators and async methods (#14655)
Allows a developer to determine *correct* overload called for *async* and *iterators*, from a stacktrace.

Matches the compiler generated containing `Type` to the source method using: 
`method.DeclaringType == StateMachineAttribute.StateMachineType` attribute to allow the stack trace to resolve the mangled method name to the correct overload.  Also appends the statemachine method name with `+` for iterators.

Resolves: dotnet/corefx#24627
@karelz

This comment has been minimized.

Copy link
Member

karelz commented Jan 25, 2018

Thanks @benaadams for pushing it through!

@lahma

This comment has been minimized.

Copy link

lahma commented Jan 25, 2018

Thank you @benaadams for having the patience and will to push forward great things that developers enjoy in their daily work!

swgillespie added a commit to swgillespie/coreclr that referenced this issue Jan 26, 2018

Resolve iterators and async methods (dotnet#14655)
Allows a developer to determine *correct* overload called for *async* and *iterators*, from a stacktrace.

Matches the compiler generated containing `Type` to the source method using: 
`method.DeclaringType == StateMachineAttribute.StateMachineType` attribute to allow the stack trace to resolve the mangled method name to the correct overload.  Also appends the statemachine method name with `+` for iterators.

Resolves: dotnet/corefx#24627
@yaakov-h

This comment has been minimized.

Copy link
Collaborator

yaakov-h commented Jan 27, 2018

Can this please be considered for porting to .NET Framework CLR?

@karelz karelz added enhancement and removed api-needs-work labels Jan 27, 2018

@karelz

This comment has been minimized.

Copy link
Member

karelz commented Jan 27, 2018

@yaakov-h it would help to have list of ALL required PRs which formed the improvement.
We will also have to check compatibility - the bar is much higher in .NET Framework.

Marking for consideration (disclaimer: I am currently not aware of ETA on when we will do next sweep of changes to port into .NET Framework)

@benaadams

This comment has been minimized.

Copy link
Collaborator

benaadams commented Jan 28, 2018

dotnet/coreclr#14652 is already netfx-port-consider

Other two are dotnet/coreclr#15781 and dotnet/coreclr#14655

@karelz

This comment has been minimized.

Copy link
Member

karelz commented Jan 29, 2018

@benaadams I would prefer to have 1 issue with clear list of all contributing PRs and let's mark that one as netfx-port-consider. We do not want to end up in situation where half of the PRs make it and half won't. At least not by accident.
Is the list of the 3 merged PRs complete?

@benaadams

This comment has been minimized.

Copy link
Collaborator

benaadams commented Jan 29, 2018

Is the list of the 3 merged PRs complete?

Yes

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment