Problems with stacktraces with async functions

[escamoteur]

for a long time, I had a problem with my flutter_command package, when the Command had caught an exception the stacktrace was always truncated. I created a simplified version of my Commands in this demo repository:

https://github.com/escamoteur/stack_trace_demo

class CommandSimple {
  final Future<void> Function() asyncFunc;
  final String name;

  final isExecuting = ValueNotifier(false);

  CommandSimple(this.asyncFunc, this.name);

  void execute() async {
    isExecuting.value = true;

    /// give the async notifications a chance to propagate
    await Future<void>.delayed(Duration.zero);

    try {
      await _execute();
    } catch (e, s) {
      print('Error executing command $name: $s');
    } finally {
      isExecuting.value = false;

      /// give the async notifications a chance to propagate
      await Future<void>.delayed(Duration.zero);
    }
  }

  Future<void> _execute() async {
    await asyncFunc();
  }
}

the execute() is assigned to the tap handler of the FAB of the counter-example. and the wrapped function fails as intended but the stacktrace that I get looks like this

I/flutter (10938): Error executing command TestCommand: #0      IOClient.send
io_client.dart:119
I/flutter (10938): <asynchronous suspension>
I/flutter (10938): dart-lang/language#1      BaseClient._sendUnstreamed
base_client.dart:93
I/flutter (10938): <asynchronous suspension>
I/flutter (10938): dart-lang/language#2      _withClient
http.dart:166
I/flutter (10938): <asynchronous suspension>
I/flutter (10938): dart-lang/language#3      level5
async_function_chain.dart:31
I/flutter (10938): <asynchronous suspension>
I/flutter (10938): dart-lang/language#4      level4
async_function_chain.dart:24
I/flutter (10938): <asynchronous suspension>
I/flutter (10938): dart-lang/language#5      level3
async_function_chain.dart:18
I/flutter (10938): <asynchronous suspension>
I/flutter (10938): dart-lang/language#6      level2
async_function_chain.dart:12
I/flutter (10938): <asynchronous suspension>
I/flutter (10938): dart-lang/language#7      level1
async_function_chain.dart:6
I/flutter (10938): <asynchronous suspension>
I/flutter (10938): dart-lang/language#8      CommandSimple._execute
command.dart:30
I/flutter (10938): <asynchronous suspension>
I/flutter (10938): dart-lang/language#9      CommandSimple.execute
command.dart:18
I/flutter (10938): <asynchronous suspension>

It starts with the execute and any information from where this was called is lost. I tried if it makes a difference if I remove the Future.delayed but it didn't. additionally, I observed that for some wrapped functions especially if they contain .then or Future.toStream even this stack trace loses steps so that it's more difficult in 'post mortem debugging' to understand what exactly has happened.

I managed in the meantime to fix this problem using the stack_trace package but I'm not sure if what I do is ok or if it will lead to memory leaks.

The improved version you can find here:

https://github.com/escamoteur/stack_trace_demo/tree/optimized-stackstrace

with that, the stack trace looks like this:

I/flutter (11752): Error executing command TestCommand: package:http/src/io_client.dart 119:7                    IOClient.send
io_client.dart:119
I/flutter (11752): package:http/src/base_client.dart 93:32                  BaseClient._sendUnstreamed
base_client.dart:93
I/flutter (11752): package:http/http.dart 166:12                            _withClient
http.dart:166
I/flutter (11752): package:stack_trace_demo/async_function_chain.dart 31:7  level5
async_function_chain.dart:31
I/flutter (11752): package:stack_trace_demo/async_function_chain.dart 24:3  level4
async_function_chain.dart:24
I/flutter (11752): package:stack_trace_demo/async_function_chain.dart 18:3  level3
async_function_chain.dart:18
I/flutter (11752): package:stack_trace_demo/async_function_chain.dart 12:3  level2
async_function_chain.dart:12
I/flutter (11752): package:stack_trace_demo/async_function_chain.dart 6:3   level1
async_function_chain.dart:6
I/flutter (11752): package:stack_trace_demo/command.dart 22:7               CommandSimple.execute (TestCommand)
command.dart:22
I/flutter (11752): ===== asynchronous gap ===========================
I/flutter (11752): package:stack_trace_demo/command.dart 15:33              CommandSimple.execute
command.dart:15
I/flutter (11752): package:stack_trace_demo/main.dart 59:36                 _MyHomePageState.build.<fn>
main.dart:59
I/flutter (11752): package:flutter/src/material/ink_well.dart 1154:21       _InkResponseState.handleTap
ink_well.dart:1154
I/flutter (11752): package:flutter/src/gestures/recognizer.dart 275:

which is pretty slick.

The first problem that the stacktrace leading up to the call of the command was missing I added at the beginning of execute

    _traceBeforeExecute = Trace.current();

and join them together with the stacktrace I get in the catch and do some cleanup of frames that don't add to the understanding

1. I would like if calling Trace.current() in a release version is ok or if it is very expensive?

2. to solve the problem of missing frames when calling the wrapped function I added the following which works but feels pretty hacky

  Future<void> _execute() async {
    final completer = Completer<void>();
    Chain.capture(
      () => asyncFunc().then(completer.complete),
      onError: completer.completeError,
      when: true,
    );
    await completer.future;
  }

which helped perfectly in another example where a Future.Stream was involved, but in this simple example the stacktrace that I get at the catch is even shorter:

flutter: Error executing command TestCommand: package:http/src/io_client.dart 119:7                   IOClient.send
io_client.dart:119
level1
async_function_chain.dart:4
CommandSimple.execute (TestCommand)

Do I use the Chain.capture wrongly? and is it at all the right tool to get better async stacktraces or will the repeated creation of ErrorZones lead to memory leaks so that its better avoided completely? Also wen adding the capture VS code breaks at the first exception although it is handled.

If someone of the team could shed some light on this topic would be really appreciated.

[lrhn]

Moved this to the stack_trace package repo, since it's questions about that package.

In general, the stack trace of a throw or StackTrace.current is capturing the actual contents of the stack at the time, up to the event loop. Since asynchronous code returns to the event loop at each asynchronous gap, the stack trace does not contain the stack that called an async function, not unless it's captured before the first await or other asynchronous delay. Otherwise that call has already returned (with a Future) so the actual stack is long gone.

The stack_trace package works by capturing the current stack at certain points (mainly where an async callback is registered, using Zone.register* methods), and when that callback is then run, using Zone.run*, any uncaught errors get caught and rethrown with the captured stack appended to the thrown stack.

That does mean capturing a lot of stack traces, where most won't be used because most code never throws. There is also some overhead on every async callback being registered and being run.

I don't know the precise implementation of this package, so I can't say how much or little that overhead is, but you should definitely only enable it for some computations, not the entire program (so don't wrap main in Chain.capture).

And how much time capturing a stack trace takes also depends on the platform. I believe the VM is fairly efficient at doing a quick capture of the stack frames, and only processing it later if you actually call toString on it. I don't know what the web compilers do, or how much it depends on the underlying JavaScript implementation.

I'd suggest that you try measuring with and without capturing stacks, e.g., by using the when argument to Chain.capture to change the code as little as possible.

And I'd also suggest to only enable this by default in debug mode. If there is something you can do, in your code, to provide context for the failure, something which doesn't have to be a stack trace, then it might be sufficient for someone trying to debug. That is, maybe collect some kind of minimal trace of the computation so far, that led up to the error, by recording logical operations rather than the rather physical stack traces.

(More philosophically, stack traces are not execution traces, they don't record how you got to where the error happens. They are instead the continuation of the current computation, what remains of the execution. We've traditionally used them for debugging because they are there, physically in memory, and it's really all we have. Sometimes we can deduce how we got to the error from what's on the stack, other times we lack some information, say because of something that happened in an earlier iteration of a loop, or because some state was optimized away and never put on the stack. Or because our compiler is smart and does inlining or tail-call optimization, which are perfectly reasonable things to do when the stack is your continuation, not if you think of it as an execution trace.)

[escamoteur]

thanks for that explanation. what isn't clear to me is why using the Chain.capture does in some situations provide a more complete stacktrace but in other situations a worse result

[escamoteur]

@lrhn actually the question is not strictly about this package because if there is a way to achieve my goal without that package I would be happy to go that way.

[lrhn]

If your problem is getting a stack trace which includes the stack up to calling an async function, as well as the stack trace after an await, then I don't think there is a better choice than this package.

It's not something the runtime tries to do for you, because it just captures the stack traces that actually exist at the time it is requested. I believe some compilation strategies may be able to do better, like using separate co-routine-like stacks for async functions and suspend them at an await, or maybe even calling directly from one async function to the await of another using the same stack. But I don't think any of our compilers actually do something like that.