dart-lang / sdk

The Dart SDK, including the VM, JS and Wasm compilers, analysis, core libraries, and more.
https://dart.dev
BSD 3-Clause "New" or "Revised" License
10.24k stars 1.57k forks source link

Empty stack traces on exceptions after dart2js #42811

Open mnordine opened 4 years ago

mnordine commented 4 years ago

Latest stable, Dart 2.8.4, all browsers.

After compiling our web app with dart2js, it seems we get empty stack traces on almost every exception or error. Not sure if it matters what compiler settings, but we usually use

release_options:
  compiler: dart2js
  dart2js_args:
    - --minify
    - --show-package-warnings
    - --trust-primitives
    - -O4

I've tried other settings as well.

In our app, we have the following code to capture uncaught expections:

final app = App();
Chain.capture(() => app..start(),
  when: true,
  onError: (error, chain)
  {
    final trace = processStackTrace(error, chain);
    print('app level error: stack trace: $trace');

    api.logError(trace);
    analytics.sendException(trace);
  });

String processStackTrace(error, Chain chain)
{
  var errorMsg = '';
  if (error is Error)
    errorMsg = '${error.toString()}\n';

  return '$errorMsg${chain.terse.toString()}';
}

Sometimes the stacks have useful information, but the vast majority of the time they are empty if when: false, and have the same values if when: true:

main.dart.js 574:57    Object.$4
org-dartlang-sdk:///sdk/lib/_internal/js_runtime/lib/js_helper.dart 2372:9  Closure.cspForwardCall
org-dartlang-sdk:///sdk/lib/async/zone.dart 1100:54                         _CustomZone.registerCallback
org-dartlang-sdk:///sdk/lib/async/zone.dart 1096:19                         _CustomZone.registerCallback[function-entry$1]
org-dartlang-sdk:///sdk/lib/async/zone.dart 1018:22                         _CustomZone.bindCallbackGuarded
org-dartlang-sdk:///sdk/lib/async/zone.dart 1238:11                         _rootScheduleMicrotask
org-dartlang-sdk:///sdk/lib/async/zone.dart 1136:55                         _CustomZone.scheduleMicrotask

JS stack trace:
main.js 574:57    Object.$4
main.js 20952:12  wp.xU
main.js 20953:28  wp.lV
main.js 20931:43  wp.tK
main.js 2060:37   vv.aae
main.js 20966:12  wp.jO

If you're wondering where the dart stack trace above comes from, on the server we use source_map_stack_trace:

import 'package:source_maps/source_maps.dart' show parse;
import 'package:source_map_stack_trace/source_map_stack_trace.dart' show mapStackTrace;

// get `sourceMap`
final mapping = parse(sourceMap);
final trace = StackTrace.fromString(jsStackTrace);
final dartStackTrace = mapStackTrace(mapping, trace, minified: true).toString();

We're on Dart 1, and trying to roll out Dart 2 to our users, but getting lots of exceptions/errors. Unfortunately due to this, we don't have any insight into what's going on.

vsmenon commented 4 years ago

Do you see different with -O2 or default? Under -O3 and -O4, dart2js does aggressive optimizations that are unsafe in the presence of errors:

https://dart.dev/tools/dart2js#options

Since you're porting, you may also want to compile and test in debug mode (with ddc) if you haven't already.

mnordine commented 4 years ago

Since you're porting, you may also want to compile and test in debug mode (with ddc) if you haven't already.

Yes, we do extensive testing in both ddc, and dart2js.

Do you see different with -O2 or default? Under -O3 and -O4, dart2js does aggressive optimizations that are unsafe in the presence of errors:

I think I've tried this, but I'll try it again to make sure.

mnordine commented 4 years ago

After using -O2, Still getting stack traces that aren't very helpful, like:

Dart stack trace:

main.js 21636:12  xw.ma
org-dartlang-sdk:///sdk/lib/async/zone.dart 1100:54       _CustomZone.registerCallback
org-dartlang-sdk:///sdk/lib/async/zone.dart 1018:22       _CustomZone.bindCallbackGuarded
org-dartlang-sdk:///sdk/lib/async/zone.dart 1238:11       _rootScheduleMicrotask
org-dartlang-sdk:///sdk/lib/async/zone.dart 1136:55       _CustomZone.scheduleMicrotask
org-dartlang-sdk:///sdk/lib/async/future_impl.dart 581:5  _Future._asyncCompleteError
org-dartlang-sdk:///sdk/lib/async/future_impl.dart 47:5   _AsyncCompleter._completeError

JS stack trace:

main.js 21636:12  xw.ma
main.js 21595:43  xw.ue
main.js 2109:37   wv.aaA
main.js 21662:12  xw.jW
main.js 20827:8   G.or
main.js 20721:25  O.eQ
mnordine commented 4 years ago

Also omitted --trust-primitives flag, same result.

mnordine commented 4 years ago

Tried -O1 (no minify) on an unfortunate subset of our users, pretty much same deal:

Dart stack trace:

main.js 37886:39  _CustomZone.registerCallback$1$1
org-dartlang-sdk:///sdk/lib/async/zone.dart 1100:54       _CustomZone.registerCallback
org-dartlang-sdk:///sdk/lib/async/zone.dart 1018:22       _CustomZone.bindCallbackGuarded
org-dartlang-sdk:///sdk/lib/async/zone.dart 1238:11       _rootScheduleMicrotask
org-dartlang-sdk:///sdk/lib/async/zone.dart 1136:55       _CustomZone.scheduleMicrotask
org-dartlang-sdk:///sdk/lib/async/future_impl.dart 581:5  _Future._asyncCompleteError
org-dartlang-sdk:///sdk/lib/async/future_impl.dart 47:5   _AsyncCompleter._completeError

JS stack trace:

main.js 37886:39  _CustomZone.registerCallback$1$1
main.js 37823:71  _CustomZone.bindCallbackGuarded$1
main.js 4872:85   StaticClosure._rootScheduleMicrotask
main.js 37921:39  _CustomZone.scheduleMicrotask$1
main.js 36371:18  _Future._asyncCompleteError$2
main.js 36158:19  _AsyncCompleter._completeError$2
sigmundch commented 4 years ago

Hi @mnordine, sorry for the delayed follow up here. Debugging production stack traces is a hard problem and I hope we can find steps that can help make it easier on you and your team.

I mentioned in your other issue (#42815) about some dart2js extensions that were designed for this purpose. For context, it was developed by iterating on issues we saw from our internal teams that were dealing with similar issues as yourself. Besides data to unwind inlined stack frames that I mentioned in the other bug, the extensions help translate minified names from error messages. For example, if the error message mentions an instance type name or a method name, we are often able to map it back.

My only suggestion at this time would be to consider testing whether package:stack_trace is affecting the result. Most of our internal teams have steered away from using Chain because it added too much overhead on their web applications. Even though it was removed for different reasons, I wonder whether that will yield better results. Unfortunately that means that you only get to see the bottom frames after the last asynchronous gap, but hopefully it may give us some clues we can use to improve your current scenario.

mnordine commented 4 years ago

Hi @sigmundch, thx, really appreciate you getting back to me.

Most of our internal teams have steered away from using Chain because it added too much overhead on their web applications

Can you share how they collect and process stack traces? Do they just use a separate Zone?

sigmundch commented 4 years ago

To be honest, I'm not sure.

Part of the cost with Chain comes from using zones and from capturing stack traces eagerly. It is possible that they don't use zones altogether. Some teams using Angular Dart may use the NgZone, but I don't know if they use it for this purpose.

I believe they generally push to ensure that all errors are captured. For example, ensuring that Futures are either awaited for or that they have an error handler attached. I believe they also use logging to capture severe or unexpected issues and get an early signal when something is not right (e.g. an unexpected internal state). Some test frameworks used to add a "catch all" by listening for any uncaught errors with window.onError, however I don't believe this is done by apps.

mnordine commented 4 years ago

@sigmundch Not sure if this helps, but at least some of the errors with empty stack traces were due to attempting to call

window.screen?.orientation?.lock('landscape');

when somehow the device was not in full screen.

Any idea why there wouldn't be a useful stack trace in those cases?

sigmundch commented 4 years ago

Interesting - not much stands out other than the fact that lock is asynchronous and returns a Future. Is that Future awaited for? or is there a .catchError on it?

mnordine commented 4 years ago

When that error was being thrown, it was neither being awaited or had .catchError on it.

sigmundch commented 4 years ago

That can explain the empty stack then. I believe that if it were awaited for (and transitively within a context where there is a try-catch or a catch error), then you'd have more details to propagate to the servers.

It can be tricky to find all places where futures are not properly wired, but luckily there are analysis tools to help. Internally, our teams enable a few analyzer lints to help diagnose and fix patterns like these. I'd recommend enabling the unawaited_futures lint, for instance. See also this article on how we use lints internally with package:pedantic.

/cc @natebosch - I recall you have experience with both async errors and package:pedantic. Is there anything else you'd recommend?

mnordine commented 4 years ago

Yeah, I'm aware of unawaited_futures. I'm not a fan of adding the ignore comment, or unawaited() in some projects where it makes sense to not await every use of a Future.

There's no way to get relevant info without await or .catchError()? I probably just don't know enough about how Futures, async/await etc.. get compiled down to JavaScript.

natebosch commented 4 years ago

In a case where the Future is completed as an error from a browser callback like this I don't think there is much that can be done. I would recommend always having an error handler on Futures that come from dart:html calls.