Frame.caller() is broken inside `Chain.capture`

[natebosch]

trafficstars

The VM started giving us different, significantly truncated StackTrace instances when running in the zone for Chain.capture. Frame.caller() relies on parsing StackTrace.current which no longer contains the caller we were looking for.

Root Cause: https://github.com/dart-lang/sdk/issues/46326

It's possible we could work around this with something like Chain.current() instead of StackTrace.current, but even with that we'd need to do specific detection that we're in the chain zone and handle the result differently.

Inside the Chain.capture the Chain.current() looks like

package:stack_trace/repro.dart 8:17           main.callee
===== asynchronous gap ===========================
dart:async/zone.dart 1286:19                  _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 45:22       _asyncThenWrapperHelper
package:stack_trace/repro.dart                main.callee
package:stack_trace/repro.dart 12:17          main.caller
package:stack_trace/repro.dart 11:22          main.caller
package:stack_trace/repro.dart 16:17          main.<fn>
package:stack_trace/repro.dart 15:23          main.<fn>
package:stack_trace/src/chain.dart 94:24      Chain.capture.<fn>
dart:async/zone.dart 1354:13                  _rootRun
dart:async/zone.dart 1258:19                  _CustomZone.run
dart:async/zone.dart 1789:10                  _runZoned
dart:async/zone.dart 1711:10                  runZoned
package:stack_trace/src/chain.dart 92:12      Chain.capture
package:stack_trace/repro.dart 15:15          main
dart:isolate-patch/isolate_patch.dart 283:19  _delayEntrypointInvocation.<fn>
dart:isolate-patch/isolate_patch.dart 184:12  _RawReceivePortImpl._handleMessage

While outside of it, it looks like

package:stack_trace/repro.dart 8:17  main.callee
===== asynchronous gap ===========================
package:stack_trace/repro.dart 12:5  main.caller
===== asynchronous gap ===========================
package:stack_trace/repro.dart 15:3  main

[natebosch]

Slightly related:

The details that we get for Chain.current also changed in that 2.12.0-29.0.dev SDK from what it had been earlier. This isn't a blocker for tweaking the logic to account for the new behavior, since we have a lower bound SDK constraint there anyway, but it's a sign that we should be careful of what details we rely on.

In earlier SDKs the Chain.current inside the chain zone would have been

package:stack_trace/repro.dart 8:17           main.callee
===== asynchronous gap ===========================
dart:async/zone.dart 1121:19                  _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 83:23       _asyncThenWrapperHelper
package:stack_trace/repro.dart                main.callee
package:stack_trace/repro.dart 12:17          main.caller
package:stack_trace/repro.dart 16:17          main.<fn>
package:stack_trace/src/chain.dart 102:24     Chain.capture.<fn>
dart:async/zone.dart 1190:13                  _rootRun
dart:async/zone.dart 1093:19                  _CustomZone.run
dart:async/zone.dart 1630:10                  _runZoned
dart:async/zone.dart 1550:10                  runZoned
package:stack_trace/src/chain.dart 100:12     Chain.capture
package:stack_trace/repro.dart 15:15          main
dart:isolate-patch/isolate_patch.dart 311:19  _startIsolate.<fn>
dart:isolate-patch/isolate_patch.dart 184:12  _RawReceivePortImpl._handleMessage

while in 2.12.0-29.0.dev and newer SDKs the main.caller and main.<fn> frames show up twice:

package:stack_trace/repro.dart 8:17           main.callee
===== asynchronous gap ===========================
dart:async/zone.dart 1121:19                  _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 40:23       _asyncThenWrapperHelper
package:stack_trace/repro.dart                main.callee
package:stack_trace/repro.dart 12:17          main.caller
package:stack_trace/repro.dart 11:22          main.caller
package:stack_trace/repro.dart 16:17          main.<fn>
package:stack_trace/repro.dart 15:23          main.<fn>
package:stack_trace/src/chain.dart 102:24     Chain.capture.<fn>
dart:async/zone.dart 1190:13                  _rootRun
dart:async/zone.dart 1093:19                  _CustomZone.run
dart:async/zone.dart 1630:10                  _runZoned
dart:async/zone.dart 1550:10                  runZoned
package:stack_trace/src/chain.dart 100:12     Chain.capture
package:stack_trace/repro.dart 15:15          main
dart:isolate-patch/isolate_patch.dart 311:19  _startIsolate.<fn>
dart:isolate-patch/isolate_patch.dart 184:12  _RawReceivePortImpl._handleMessage

[radzish]

Following case could be related:

import 'dart:async';

import 'package:stack_trace/stack_trace.dart';

Future<void> main(List<String> arguments) async {
  await Chain.capture(() async {
    await methodA();
  });
}

Future<void> methodA() async {
  await methodB();
}

Future<void> methodB() async {
  await prepare();
  await work();
}

Future<void> prepare() async {}

Future<void> work() async => throw "work error";

Output is following:

Unhandled exception:
work error
bin/dart_async_exceptions.dart 22:30          work
bin/dart_async_exceptions.dart 17:9           methodB
===== asynchronous gap ===========================
dart:async/zone.dart 1294:19                  _CustomZone.registerBinaryCallback
dart:async-patch/async_patch.dart 61:8        _asyncErrorWrapperHelper
bin/dart_async_exceptions.dart                main.<fn>
package:stack_trace/src/chain.dart 94:24      Chain.capture.<fn>
dart:async/zone.dart 1354:13                  _rootRun
dart:async/zone.dart 1258:19                  _CustomZone.run
dart:async/zone.dart 1789:10                  _runZoned
dart:async/zone.dart 1711:10                  runZoned
package:stack_trace/src/chain.dart 92:12      Chain.capture
bin/dart_async_exceptions.dart 6:15           main
dart:isolate-patch/isolate_patch.dart 281:32  _delayEntrypointInvocation.<fn>
dart:isolate-patch/isolate_patch.dart 184:12  _RawReceivePortImpl._handleMessage

As you can see methodA invocation is missing

Now if you remove Chain.capture and just run await methodA(); from main, output is like this:

Unhandled exception:
work error
#0      work (file:///home/kernel/work/stuff/projects/dart-async-exceptions/bin/dart_async_exceptions.dart:22:30)
#1      methodB (file:///home/kernel/work/stuff/projects/dart-async-exceptions/bin/dart_async_exceptions.dart:17:9)
<asynchronous suspension>
#2      methodA (file:///home/kernel/work/stuff/projects/dart-async-exceptions/bin/dart_async_exceptions.dart:12:3)
<asynchronous suspension>
#3      main (file:///home/kernel/work/stuff/projects/dart-async-exceptions/bin/dart_async_exceptions.dart:7:5)
<asynchronous suspension>

Which is nice and correct trace.

Dart version: 2.13.3 (stable)

[mraleph]

I think this is fixed by https://github.com/dart-lang/stack_trace/commit/d3e4c4d633eca379462dd4473b8995761155ee84 and https://github.com/dart-lang/sdk/commit/a52f2b96179ebdf29c38cab47e73dd1c6ec6bdff

[radzish]

@mraleph , I just tried with 1.11.1 with latest dart sdk build (as of today: 3.2.0-edge.dd712accf4cb04860dd1ab7a35679e94dc8d6cad (be) (Wed Jul 26 10:58:09 2023 +0000) on "linux_x64") and it still does not solve case I mentioned here: https://github.com/dart-lang/stack_trace/issues/111#issuecomment-868674265

[mraleph]

Hmm, indeed stack trace produced by Chain.capture is still broken. I guess something in the stack_trace internals is still not working properly. But StackTrace.current is actually producing normal stuff now (if you print StaceTrace.current at the place where you throw) and so will the debugger.