Is it possible to get a good stack trace with .NET async methods?

问题

I have the following sample code setup in a WebApi application:

[HttpGet]
public double GetValueAction()
{
    return this.GetValue().Result;
}

public async Task<double> GetValue()
{
    return await this.GetValue2().ConfigureAwait(false);
}

public async Task<double> GetValue2()
{
    throw new InvalidOperationException("Couldn't get value!");
}

Sadly, when GetValueAction gets hit, the stack trace that comes back is:

    " at MyProject.Controllers.ValuesController.<GetValue2>d__3.MoveNext() in c:\dev\MyProject\MyProject\Controllers\ValuesController.cs:line 61 --- 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.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
at MyProject.Controllers.ValuesController.<GetValue>d__0.MoveNext() in c:\dev\MyProject\MyProject\Controllers\ValuesController.cs:line 56"

Thus, I get (mangled) GetValue2 and GetValue in the trace, but no mention of GetValueAction. Am I doing something wrong? Is there another pattern that will get me more complete stack traces?

EDIT: my goal is not to write code relying on the stack trace, but instead to make failures in async methods easier to debug.

这个似乎只在asp.net有问题？我用console项目测试，看起来是正常的堆栈

System.AggregateException: One or more errors occurred. ---> System.InvalidOperationException: Couldn't get value!
at AsyncExceptionTest.ControllerTest.<GetValue2>d__2.MoveNext() in C:\workspace\GitHub\ChuckLu\ChuckTest\async-await-test\AsyncExceptionTest\ControllerTest.cs:line 23
--- 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.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
at AsyncExceptionTest.ControllerTest.<GetValue>d__1.MoveNext() in C:\workspace\GitHub\ChuckLu\ChuckTest\async-await-test\AsyncExceptionTest\ControllerTest.cs:line 18
--- End of inner exception stack trace ---
at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
at System.Threading.Tasks.Task`1.get_Result()
at AsyncExceptionTest.ControllerTest.GetValueAction() in C:\workspace\GitHub\ChuckLu\ChuckTest\async-await-test\AsyncExceptionTest\ControllerTest.cs:line 13
at AsyncExceptionTest.Program.Main(String[] args) in C:\workspace\GitHub\ChuckLu\ChuckTest\async-await-test\AsyncExceptionTest\Program.cs:line 16
---> (Inner Exception #0) System.InvalidOperationException: Couldn't get value!
at AsyncExceptionTest.ControllerTest.<GetValue2>d__2.MoveNext() in C:\workspace\GitHub\ChuckLu\ChuckTest\async-await-test\AsyncExceptionTest\ControllerTest.cs:line 23
--- 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.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
at AsyncExceptionTest.ControllerTest.<GetValue>d__1.MoveNext() in C:\workspace\GitHub\ChuckLu\ChuckTest\async-await-test\AsyncExceptionTest\ControllerTest.cs:line 18<---

回答1

This question and its highest voted answer were written back in 2013. Things have improved since then.

.NET Core 2.1 now provides intelligible async stack traces out of the box; see Stacktrace improvements in .NET Core 2.1.

For those still on .NET Framework, there's an excellent NuGet package that fixes up async (and many other obscurities) in stack traces: Ben.Demystifier. The advantage of this package over other suggestions is that it doesn't require changes to the throwing code or assembly; you simply have to call Demystify or ToStringDemystified on the caught exception.

Applying this to your code:

System.AggregateException: One or more errors occurred. ---> System.InvalidOperationException: Couldn't get value!
   at async Task<double> ValuesController.GetValue2()
   at async Task<double> ValuesController.GetValue()
   --- End of inner exception stack trace ---
   at void System.Threading.Tasks.Task.ThrowIfExceptional(bool includeTaskCanceledExceptions)
   at TResult System.Threading.Tasks.Task<TResult>.GetResultCore(bool waitCompletionNotification)
   at TResult System.Threading.Tasks.Task<TResult>.get_Result()
   at double ValuesController.GetValueAction()
   at void Program.Main(string[] args)
---> (Inner Exception #0) System.InvalidOperationException: Couldn't get value!
   at async Task<double> ValuesController.GetValue2()
   at async Task<double> ValuesController.GetValue()<---

This is admittedly still a bit convoluted due to your use of Task<T>.Result. If you convert your GetValueAction method to async (in the spirit of async all the way), you would get the expected clean result:

System.InvalidOperationException: Couldn't get value!
   at async Task<double> ValuesController.GetValue2()
   at async Task<double> ValuesController.GetValue()
   at async Task<double> ValuesController.GetValueAction()

回答2

There is a nice nuget extension for this by the async/await king.

https://www.nuget.org/packages/AsyncStackTraceEx/

you need to change your await call from

Await DownloadAsync(url)

Await DownloadAsync(url).Log()

Finally, in the catch block, just call

ex.StackTraceEx()

One important note: This method can only be called once and ex.StackTrace must not be evaluated before. It seems that the stack can only be read once.

回答3

First off, stack traces don't do what most people think they do. They can be useful during debugging, but are not intended for runtime use, particularly on ASP.NET.

Also, the stack trace is technically about where the code is returning to, not where the code came from. With simple (synchronous) code, the two are the same: the code always returns to whatever method called it. However, with asynchronous code, those two are different. Again, the stack trace tells you what will happen next, but you're interested in what happened in the past.

So, the stack frame is not the correct answer for your needs. Eric Lippert explains this well in his answer here.

The MSDN article that @ColeCampbell linked to describes one way to track "casuality chains" (where the code came from) with async code. Unfortunately, that approach is limited (e.g., it doesn't handle fork/join scenarios); however, it is the only approach I know of that does work in Windows Store applications.

Since you're on ASP.NET with the full .NET 4.5 runtime, you have access to a more powerful solution for tracking casuality chains: the logical call context. Your async methods do have to "opt in", though, so you don't get it for free like you would with a stack trace. I just wrote this up in a blog post that is not yet published, so you're getting a preview. :)

You can build a "stack" of calls yourself around the logical call context as such:

public static class MyStack
{
  // (Part A) Provide strongly-typed access to the current stack
  private static readonly string slotName = Guid.NewGuid().ToString("N");
  private static ImmutableStack<string> CurrentStack
  {
    get
    {
      var ret = CallContext.LogicalGetData(name) as ImmutableStack<string>;
      return ret ?? ImmutableStack.Create<string>();
    }
    set { CallContext.LogicalSetData(name, value); }
  }

  // (Part B) Provide an API appropriate for pushing and popping the stack
  public static IDisposable Push([CallerMemberName] string context = "")
  {
    CurrentStack = CurrentStack.Push(context);
    return new PopWhenDisposed();
  }
  private static void Pop() { CurrentContext = CurrentContext.Pop(); }
  private sealed class PopWhenDisposed : IDisposable
  {
    private bool disposed;
    public void Dispose()
    {
      if (disposed) return;
      Pop();
      disposed = true;
    }
  }

  // (Part C) Provide an API to read the current stack.
  public static string CurrentStackString
  {
    get { return string.Join(" ", CurrentStack.Reverse()); }
  }
}

(ImmutableStack is available here). You can then use it like this:

static async Task SomeWork()
{
  using (MyStack.Push())
  {
    ...
    Console.WriteLine(MyStack.CurrentStackAsString + ": Hi!");
  }
}

The nice thing about this approach is that it works with all async code: fork/join, custom awaitables, ConfigureAwait(false), etc. The disadvantage is that you're adding some overhead. Also, this approach only works on .NET 4.5; the logical call context on .NET 4.0 is not async-aware and will not work correctly.

Update: I released a NuGet package (described on my blog) that uses PostSharp to inject the pushes and pops automatically. So getting a good trace should be a lot simpler now.

使用Ben.Demystifier后，得到的堆栈信息

System.AggregateException: One or more errors occurred. ---> System.InvalidOperationException: Couldn't get value!
at async Task<double> AsyncExceptionTest.ControllerTest.GetValue2() in C:/workspace/GitHub/ChuckLu/ChuckTest/async-await-test/AsyncExceptionTest/ControllerTest.cs:line 23
at async Task<double> AsyncExceptionTest.ControllerTest.GetValue() in C:/workspace/GitHub/ChuckLu/ChuckTest/async-await-test/AsyncExceptionTest/ControllerTest.cs:line 18
--- End of inner exception stack trace ---
at void System.Threading.Tasks.Task.ThrowIfExceptional(bool includeTaskCanceledExceptions)
at TResult System.Threading.Tasks.Task<TResult>.GetResultCore(bool waitCompletionNotification)
at TResult System.Threading.Tasks.Task<TResult>.get_Result()
at double AsyncExceptionTest.ControllerTest.GetValueAction() in C:/workspace/GitHub/ChuckLu/ChuckTest/async-await-test/AsyncExceptionTest/ControllerTest.cs:line 13
at void AsyncExceptionTest.Program.Main(string[] args) in C:/workspace/GitHub/ChuckLu/ChuckTest/async-await-test/AsyncExceptionTest/Program.cs:line 17
---> (Inner Exception #0) System.InvalidOperationException: Couldn't get value!
at async Task<double> AsyncExceptionTest.ControllerTest.GetValue2() in C:/workspace/GitHub/ChuckLu/ChuckTest/async-await-test/AsyncExceptionTest/ControllerTest.cs:line 23
at async Task<double> AsyncExceptionTest.ControllerTest.GetValue() in C:/workspace/GitHub/ChuckLu/ChuckTest/async-await-test/AsyncExceptionTest/ControllerTest.cs:line 18<---