Sdk: Incorrect Line Numbers in Source-mapped Stack Traces

Created on 17 Oct 2016 · 19Comments · Source: dart-lang/sdk

When Chrome applies source maps generated by dart2js to a stack trace I am finding the line numbers can be off by at least one or two lines. The correct line number can precede or succeed the line number reported by Chrome. This makes interpretation of the stack traces generated in a production application more difficult to interpret.

Here is a simple app that demonstrates the problem. It renders a button that throws an exception when clicked. In this case the line number reported by Chrome precedes the line the exception is actually thrown on by one.

pubspec.yaml:

name: example

dependencies:
  browser: ">=0.10.0 <0.11.0"

transformers:
- $dart2js:
    sourceMaps: true

webindex.html:

<html>
<head><title>Demo</title></head>
<body>
    <script type="application/dart" src="main.dart"></script>
    <script src="/packages/browser/dart.js"></script>
</body>
</html>

webmain.dart:

import 'dart:html';

void main() {
  addElements();
}

void addElements() {
  querySelector('body')
    ..append(new ButtonElement()
      ..text = 'Throw Exception'
      ..onClick.listen(_handleExceptionButton));
}

void _handleExceptionButton(_) {   // <--- Line 14
  throw new IntegerDivisionByZeroException();   // <--- Expected location
}

Steps to generate stack trace in Chrome:

Open Chrome
Open the dev tools
Edit dev tools settings and ensure Enable JavaScript source maps is checked
pub serve
Navigate to localhost:8080 in Chrome
Click the button labeled Throw Exception
Switch to the dev tools Console
You should see an uncaught exception that looks like:

I would expect the stack trace in Chrome to report line 15 rather than 14. In this case the line number is only off by one, but in other circumstances I've observed it to be off by three.

I've tested this with versions 1.14.0 and 1.19.1 of dart and version 53.0.2785.143 of Chrome running on macOS Sierra.

closed-obsolete dart2js-sourcemap web-dart2js

Source

todbachman-wf

👍1

Most helpful comment

Thanks for the thorough tests! We're working on a new source map engine that, in it's current state, handles the first problem (synchronous code) but not the latter (asynchronous code), yet.

johnniwinther on 17 Nov 2016

🎉2

All 19 comments

+1 this can be very misleading when diagnosing issues in production

travissanderson-wf on 19 Oct 2016

I was doing some testing, because I want to use the stack trace for sentry.io error reporting.
If you throw a Exception in a only using synchronous function calls the stacktrace points points to the dart function declaration in which the exception is thrown,
this also works when calling functions from other packages.

But as soon as there is a async function in the call stack, the source map does very weird things and does not match up with the source code at all.
I have thrown together a small test package to illustrate the behavior.

Using:
Dart VM version: 1.20.1 (Wed Oct 12 15:07:10 2016) on "linux_x64"
Chrome 54.0.2840.59 (64-bit)
Command: pub serve

pubspec.yml

name: 'dart_exception_test'
version: 0.0.1
description: An absolute bare-bones web app.

environment:
  sdk: '>=1.0.0 <2.0.0'

dependencies:
  browser: '>=0.10.0 <0.11.0'
  dart_to_js_script_rewriter: '^1.0.1'

transformers:
- dart_to_js_script_rewriter
- $dart2js:
    sourceMaps: true

web/main.dart

// Copyright (c) 2016, Nico Schieder. All rights reserved. Use of this source code
// is governed by a BSD-style license that can be found in the LICENSE file.

import 'dart:html';
import 'dart:async';
import 'package:dart_exception_test/dart_exception_test.dart';

main() {
  test3();
  test2();
  test1();
}

test1() {
  throw new Exception('main.dart - Sync Exception');
}

test2() async {
  throw new Exception('main.dart - Async Exception');
}

test3() async {
  // exception of package
  testPackage();
}

lib/dart_exception_test.dart

library dart_exception_test;

testPackage() {
  throw new Exception('package - Sync Exception');
}

Output:

1. Sync Exception

Behavior: Stacktrace points to declaration of test1()

main.dart

// ...
main() {
  // test3();
  // test2();
  test1();
}
// ...

Stacktrace:
dart-exception-sync

2. Async Exception

Behavior: Stacktrace points to the closing bracket of main()?

main.dart

// ...
main() {
  // test3();
  test2();
  // test1();
}
// ...

Stacktrace:
dart-exception-async-main

3. Other package indirect Async

Behavior: Stacktrace points to the closing bracket of main() and the origin point of the exception cannot be seen at all.

main.dart

// ...
main() {
  test3();
  // test2();
  // test1();
}
// ...

Stacktrace:
dart-exception-package-indirect-async

Package:
dart-exception-test.tar.gz

I hope this helps finding the issues with source maps.

thetechnick on 21 Oct 2016

@TheTechNick that is a really good point, we use the async marker _liberally_ in our code and the lines can be way off. There's also some behind the scenes magic that happens when you use that marker, maybe the source mapping isn't correctly accounting for that.

travissanderson-wf on 21 Oct 2016

Thanks for the thorough tests! We're working on a new source map engine that, in it's current state, handles the first problem (synchronous code) but not the latter (asynchronous code), yet.

johnniwinther on 17 Nov 2016

🎉2

Is there anything we can watch regarding progress on the new engine or any ETA you could give? This is a daily problem for us right now.

travissanderson-wf on 17 Nov 2016

Thanks for the thorough tests! We're working on a new source map engine that, in it's current state, handles the first problem (synchronous code) but not the latter (asynchronous code), yet.

So the new engine does not generate correct maps if there is something async in the call stack?
Does your "yet" mean that supporting source maps in a async context is a feature on your roadmap?
Can we support you somehow?

thetechnick on 17 Nov 2016

You can try out the new engine when running dart2js from the command line using the option --use-new-source-info . The option and the fix for synchronous code is in 1.21.0-dev.7.0 . Any feedback on the quality of the new engine will be helpful in making it ready as the default engine.

I've looked into the asynchronous code and found that it contained no source mapping neither in the old nor the new engine. I'm working on a CL providing source mapping for the main parts of async code. This will go in today and should be part of the next dev release.

johnniwinther on 18 Nov 2016

🎉1

@johnniwinther would this be the correct way to use that via pubspec.yaml?

transformers:
  - $dart2js:
      sourceMaps: true
      commandLineOptions: [--use-new-source-info]

travissanderson-wf on 5 Jan 2017

I'm assuming this is available in the stable release of Dart SDK 1.21.0, too.. is there a way to inspect the sourcemap to verify it was generated with the new one instead of the old/current one?

travissanderson-wf on 5 Jan 2017

It the correct pubspec.yaml parameters but there is no way to verify that the new engine is used (besides seeing you get a different .js.map file in the output).

The option is available in the 1.21 stable release.

johnniwinther on 6 Jan 2017

What's the current status regarding accuracy for the new engine? Unfortunately I don't have a reproducing example but we are getting a JS stack trace that maps a null pointer that seems impossible. The code below is a simplified example of the code that is returning a null pointer on the line with return _items[index].

The error we are seeing is Uncaught exception: NullError: method not found: 'd' on null, which doesn't really make sense for the line indicated by the mapping.

class Manager {
  Example example = new Example();

  dispose() {
    example?.dispose();
    example = null;
  }
}

class Example {
  Map<int, String> _items = new Map(); // initialized at instantiation and never nulled out 

  String getItemValue(int index) {
    return _items[index];
  }
}

travissanderson-wf on 6 Jan 2017

So I was able to talk to someone that hit this exception and figured out how to reproduce it. The error in Dart is much more helpful and showed that the code was trying to call a method on a null instance of Example, and the method it was trying to call was getItemValue. This is from a private repo so I can't exactly share the code but the whole map seems to be wrong other than the very top of the trace being within 1 line of the method that was called on null.

travissanderson-wf on 6 Jan 2017

The name 'd' is probably due to the use of minification. If you turn that off the name will probably be something like 'getItemValue$0' which makes a bit more sense. Unfortunately, the message you get for null pointer exceptions is generated by JavaScript directly, which is why minification matters here.

johnniwinther on 9 Jan 2017

Do you use async/await? If so, only top-most synchronous part of the call-stack makes sense (the rest being the call-stack for the event queue handling asynchronous calls).

johnniwinther on 9 Jan 2017

Sorry, I meant that error doesn't make sense for the line because it was pointing at the line of the return instead of the method declaration. We do use minification and we use async/await quite a bit. We have a flag to enable Chain.capture but it really kills performance in some browsers.

I added a Manager class above to flesh out what I'm seeing. It was confusing to diagnose a production error because in the Dart error the top of the stack does not refer to the Example file that defines the class for the null object, it only refers to the calling file (Manager) that hit the null pointer. In the mapped Javascript stack it makes it look as if the exception happened in Example instead of in Manager. In fact, even using the new engine the rest of the stack still seems to be completely wrong after mapping, referring to files that are not involved nor do they actually call each other.

travissanderson-wf on 9 Jan 2017

Sounds bad :( I'd appreciate if you can create an example, maybe mailing me directly.

Regarding the status of the new engine, these are known issues and their state:

Source sourcemapping of every steppable and breakable point in synchronous code (calls, throws, returns, loops, function returns) (Done)
Support sourcemapping of JavaScript embedded in helper methods. (Unimplemented)
Preserve sourcemapping in synchronous parts of async/await code. (Almost done; needs better coverage)
Support sourcemapping of event loop code for the asynchronous part of async/await code. (Unimplemented)
Support inlining (multiple stackframes for a single call) and "outlining" (hiding of stackframes from helper methods). (Unimplemented: This is not supported by the sourcemap format.)

johnniwinther on 10 Jan 2017

Sure thing, I will see if I can get a reproducing case and hit you up directly. Thanks.

travissanderson-wf on 10 Jan 2017

Just to update this thread, I reported an off-by-one reproducing case to Johnni that will be resolved.

I also showed him an instance of the map that looked completely wrong. It turns out that is retracer (and browser's) best effort at reading the map for an unmapped region of code; the code is javascript boilerplate for setting up a Dart application environment and there's not many good options for how to handle that in a map that works well with both mapping and debugging.

travissanderson-wf on 11 Jan 2017

Work on Dart SDK 1 has stopped. If this is still an issue in Dart2, please file a new issue.