Suggestion: supporting asynchronous stack traces for async/await in TypeScript

[ntrrgc]

Background

Currently TypeScript supports the async and await keywords when ES6 is set as build target, using generators under the hood. This is a promising feature as it allows you to write synchronous looking code that is much easier to write and understand than in a traditional callback based approach. Take for instance this code.

function sleep(time) {
    return new Promise(function (resolve) {
        setTimeout(resolve, time);
    });
}

async function fun1() {
    console.log('Step 1');
    await sleep(500);
    console.log('Step 2');
    await sleep(500);
    const ret = await fun2();
    console.log(`Done in ${ret} steps`);
}

async function fun2() {
    console.log('Step 3');
    await sleep(500);
    return 3;
}

function main() {
    fun1().then(() => {
        console.log('Finished program');
    }).catch((err) => {
        console.error(err.stack);
    })
}
main();

Being able to write code in this way is a big step toward making node.js a comfortable and productive platform for writing server applications. Unfortunately, there is a catch, that really is not something new with generators, but anyway that destroys all the productivity you may hoped to get from this feature: Neither node.js or TypeScript implement asynchronous stack traces on exceptions (also known as long stack traces).

As a consequence, if you edit fun2() like this, making it fail in an obvious way...

async function fun2() {
    throw new Error('miau');
}

You will get this error on runtime:

Error: foo error
    at /tmp/untitled/main.js:26:15
    at next (native)
    at /tmp/untitled/main.js:6:65
    at __awaiter (/tmp/untitled/main.js:2:12)
    at fun2 (/tmp/untitled/main.js:25:12)
    at /tmp/untitled/main.js:20:27
    at next (native)
    at fulfilled (/tmp/untitled/main.js:3:58)

Not a single trace of fun1, which was the actual fun2 caller. It's not hard to guess what this means in codebases larger than this extremely short example: hours of console.log() calls in every piece of code that may be even remotely related to the error, frustration and finally anger when the source of the error is found, which more often than not is a trivial error on the caller function. Then you wonder how so many people are using node.js for writing web applications and what's wrong with them, suffering in this way.

Existing solutions: Bluebird

This issue is not new and fortunately a few people have actually tried to tackle it down. For instance, the promise library bluebird includes support for long stack traces: chained promises get the stack trace of the previous promise, which is added to error traces if a rejection happens.

Here is some code very similar to the TypeScript/ES6 async/await example before, but using Promise.coroutine() from Bluebird:

const Promise = require('bluebird');
Promise.config({
    longStackTraces: true
});

function sleep(time) {
    return new Promise(function (resolve) {
        setTimeout(resolve, time);
    });
}

fun1 = Promise.coroutine(fun1);
function* fun1() {
    console.log('Step 1');
    yield sleep(500);
    console.log('Step 2');
    yield sleep(500);
    const ret = yield fun2();
    console.log("Done in " + ret + " steps");
}

fun2 = Promise.coroutine(fun2);
function* fun2() {
    throw new Error('foo error');
}

function main() {
    fun1().then(() => {
        console.log('Finished program');
    }).catch((err) => {
        console.error(err.stack);
    });
}
main();

It generates this stack trace, which is relatively compact and definitively useful:

Error: foo error
    at fun2 (/tmp/untitled/test-bluebird.js:24:11)
    at next (native)
From previous event:
    at fun1 (/tmp/untitled/test-bluebird.js:18:23)
    at next (native)
    at tryOnImmediate (timers.js:534:15)
    at processImmediate [as _immediateCallback] (timers.js:514:5)
From previous event:
    at main (/tmp/untitled/test-bluebird.js:28:5)
    at Object.<anonymous> (/tmp/untitled/test-bluebird.js:34:1)
    at Module._compile (module.js:413:34)
    at Object.Module._extensions..js (module.js:422:10)
    at Module.load (module.js:357:32)
    at Function.Module._load (module.js:314:12)
    at Function.Module.runMain (module.js:447:10)
    at startup (node.js:146:18)
    at node.js:404:3

Bluebird gotchas

Everything is awesome and beautiful until you mix some old school callback code there...

function halfBakedPromiser() {
    return new Promise(function promiseResolver(resolve) {
        setTimeout(function timeoutCallback() {
            throw new Error('callback error');
        }, 100);
    })
}

fun2 = Promise.coroutine(fun2);
function* fun2() {
    yield halfBakedPromiser();
}

and suddenly no traceback (well, technically it's still a traceback, but it's almost useless):

/tmp/untitled/test-bluebird.js:25
            throw new Error('callback error');
            ^

Error: callback error
    at timeoutCallback [as _onTimeout] (/tmp/untitled/test-bluebird.js:25:19)
    at Timer.listOnTimeout (timers.js:92:15)

... or even promises made with another library, including ES6 native promises.

function foreignPromiser() {
    return new global.Promise(function promiseResolver(resolve) {
        setTimeout(resolve, 100);
    }).then(function thenResolver() {
        throw new Error('other promise error');
    });
}

fun2 = Promise.coroutine(fun2);
function* fun2() {
    yield foreignPromiser();
}

In this case the trace still preserves the information from previous Bluebird promises but the last one. That one has gone missing since setTimeout was called by the native Promise constructor.

Error: other promise error
    at thenResolver (/tmp/untitled/test-bluebird.js:26:15)
From previous event:
    at fun1 (/tmp/untitled/test-bluebird.js:18:23)
    at next (native)
    at processImmediate [as _immediateCallback] (timers.js:383:17)
From previous event:
    at main (/tmp/untitled/test-bluebird.js:36:5)
    at Object.<anonymous> (/tmp/untitled/test-bluebird.js:42:1)
    at Module._compile (module.js:413:34)
    at Object.Module._extensions..js (module.js:422:10)
    at Module.load (module.js:357:32)
    at Function.Module._load (module.js:314:12)
    at Function.Module.runMain (module.js:447:10)
    at startup (node.js:141:18)
    at node.js:933:3

So far Bluebird is a good solution for tracing asynchronous code as long as you always do all asynchronous work inside a promise and don't mix other promise libraries. Fortunately the A+ standard exists to make them replaceable to some extent and many libraries allow changing their promise constructor.

Other solutions

Longjohn

There are other approaches to tackle this problem. For instance, longjohn hooks node.js EventEmitter in order to save stack traces the instant asynchronous actions are queued and wraps the callbacks in order to recover the previous traces in case of an error.

longjohn is very useful to tackle down the source of errors for dangling callbacks like in the case of halfBakedPromiser() before. It's not very adequate to use plain callbacks relying in longjohn as the error catcher though, as it just modifies the stack property of the error when it escapes the callback and then rethrows it. After that the process dies, killing all active connections in the case of a server (long lived ones e.g. WebSocket included) unless some sort of deprecated hack like node domains is used.

longjohn is not able to improve the reporting for foreignPromise() and shows an even less useful output if Bluebird long stack traces are disabled.

For well behaved promises, when used alone (with longStackTraces: false set in Bluebird) longjohn is also able to show a useful traceback. It's different than the one generated by Bluebird in that the same asynchronous function/generator call may appear more than once, once for each time it yielded.

When used with longStackTraces: true, longjohn conflicts a bit with bluebird, since both add calls to the stack on their own way. longjohn calls appear at the end, after startup (node.js). In consequence, the generated call list is a bit weird since it actually goes down, up and down again.

Asynchronous stack frames (Chrome only)

Chrome debugger has recently implemented support for asynchronous stack traces. This works similarly to longjohn in that it follows code through asynchronous boundaries, but allows full inspecting of the value of the variables in previous frames too. This feature is only enabled when the developer tools are open, so it's not possible to get this enriched stack trace in application code (e.g. to send an automatic bug report).

Proposal

Since there are many ways in which asynchronous code may be structured in an application in order to make error processing and debugging manageable at large scale it may be desirable to be able to adapt TypeScript output code to them when the async/await keywords are used.

At the moment TypeScript always emits a polyfill like this in all files using async...

var __awaiter = (this && this.__awaiter) || function (thisArg, _arguments, P, generator) {
    return new (P || (P = Promise))(function (resolve, reject) {
        function fulfilled(value) { try { step(generator.next(value)); } catch (e) { reject(e); } }
        function rejected(value) { try { step(generator.throw(value)); } catch (e) { reject(e); } }
        function step(result) { result.done ? resolve(result.value) : new P(function (resolve) { resolve(result.value); }).then(fulfilled, rejected); }
        step((generator = generator.apply(thisArg, _arguments)).next());
    });
};

... with functions like this ...

async function fun1() {
    await sleep(500);
}

... being turned into:

function fun1() {
    return __awaiter(this, void 0, void 0, function* () {
        yield sleep(500);
    });
}

A user may want to replace it with a Promise.coroutine implementation in order to get sane tracebacks when debugging, like this:

var __PromiseBluebird = require('bluebird');
var __awaiter = function (thisArg, _arguments, P, generator) {
    return __PromiseBluebird.coroutine(generator).apply(thisArg, _arguments);
};

Or they may even want to remove the __awaiter altogether in order to avoid it popping on the stack trace and avoid creating unecessary closures. In that case this output would be preferred:

fun1 = __PromiseBluebird.coroutine(fun1);
function* fun1() {
    yield sleep(500);
});

Replacing the awaiter polyfill could be done quite simply with the tsconfig.json. For instance, a new optional property awaiterPolyfillDefinition would store a path relative from the TypeScript project root pointing to a .js file with the new polyfill.

Replacing the how the async functions are emitted as JavaScript code in order to remove the __awaiter call may be harder on the other hand due to hoisting. The .coroutine() call would have to be hoisted above any usage of the function or otherwise it would be called as a generator instead of as a promise returning function, causing a runtime error.

[rbuckton]

It is already possible to replace the implementation of __awaiter in TypeScript, as in your example above:

var __PromiseBluebird = require('bluebird');
var __awaiter = function (thisArg, _arguments, P, generator) {
    return __PromiseBluebird.coroutine(generator).apply(thisArg, _arguments);
};

We do plan to have some broad support for loading helpers from an external helpers library in the future, though nothing quite so granular as you are proposing with awaiterPolyfillDefinition.

[hayeah]

@rbuckton Do you mean explicitly overwriting __awaiter? Like:

async function foo() {
  await foo();
  return 10;
}

function __awaiter() {
// ...
}

[rbuckton]

@hayeah, yes.

[ntrrgc]

Adding code at the top to replace __awaiter works, but it's a bit error prone since you need to do it for each file -- failure to do so will cause competing implementations and generates more code than really necessary.

Also, note you can't just use a function definition like @hayeah did, you need to assign the function with var __awaiter = function __awaiter() { ... } instead. Otherwise, function hoisting will cause your definition to float to the very top of the file and the TypeScript implementation will override it.

[kitsonk]

Adding code at the top to replace __awaiter works, but it's a bit error prone since you need to do it for each file -- failure to do so will cause competing implementations and generates more code than really necessary.

Currently you can provide noEmitHelpers as a compiler flag and provide your helpers some other way. The team are working on making that more maintainable in the future (see #3364).

[ntrrgc]

Unfortunately I've found replacing __awaiter code to create a Bluebird coroutine and immediately call it not only is inefficient, but also it does not produce async stack traces when there are nested calls. 😞

The following test case shows it failing:

const Promise = require('bluebird');
Promise.config({
  longStackTraces: true
});

function __awaiter(generator) {
  return Promise.coroutine(generator)();
}

function sleep(time) {
  return new Promise(function (resolve) {
    setTimeout(resolve, time);
  });
}

function fun1() {
  return __awaiter(function* fun1_cor() {
    console.log('Doing work...');
    yield sleep(50);
    const ret = yield fun2();
    console.log("Done in " + ret + " steps");
  })
}

function fun2() {
  return __awaiter(function* fun2_cor () {
    throw new Error('foo error');
  })
}

function main() {
  fun1().then(() => {
    console.log('Finished program');
  }).catch((err) => {
    console.error(err.stack);
  });
}
main();

It produces this stack trace, where line 20 (const ret = yield fun2();) cannot be found.

Doing work...
Error: foo error
    at fun2_cor (/home/ntrrgc/tmp/untitled3/untitled/testcase.js:27:11)
    at next (native)
From previous event:
    at __awaiter (/home/ntrrgc/tmp/untitled3/untitled/testcase.js:7:38)
    at fun1 (/home/ntrrgc/tmp/untitled3/untitled/testcase.js:17:10)
    at main (/home/ntrrgc/tmp/untitled3/untitled/testcase.js:32:3)
    at Object.<anonymous> (/home/ntrrgc/tmp/untitled3/untitled/testcase.js:38:1)
    at Module._compile (module.js:413:34)
    at Object.Module._extensions..js (module.js:422:10)
    at Module.load (module.js:357:32)
    at Function.Module._load (module.js:314:12)
    at Function.Module.runMain (module.js:447:10)
    at startup (node.js:141:18)
    at node.js:933:3

On the other hand, creating them in __awaiter and calling them in the outer function works, but it would be even better to only create the coroutines once, like this:

const Promise = require('bluebird');
Promise.config({
  longStackTraces: true
});

function __async_gen(generator) {
  return Promise.coroutine(generator);
}

function sleep(time) {
  return new Promise(function (resolve) {
    setTimeout(resolve, time);
  });
}

const fun1 = __async_gen(function* fun1() {
  console.log('Doing work...');
  yield sleep(50);
  const ret = yield fun2();
  console.log("Done in " + ret + " steps");
});

const fun2 = __async_gen(function* fun2 () {
  throw new Error('foo error');
});

function main() {
  fun1().then(() => {
    console.log('Finished program');
  }).catch((err) => {
    console.error(err.stack);
  });
}
main();

This way is not only more efficient, but also produces cleaner, complete tracebacks:

Doing work...
Error: foo error
    at fun2 (/home/ntrrgc/tmp/untitled3/untitled/testcase.js:24:9)
    at next (native)
From previous event:
    at fun1 (/home/ntrrgc/tmp/untitled3/untitled/testcase.js:19:21)
    at next (native)
    at processImmediate [as _immediateCallback] (timers.js:383:17)
From previous event:
    at main (/home/ntrrgc/tmp/untitled3/untitled/testcase.js:28:3)
    at Object.<anonymous> (/home/ntrrgc/tmp/untitled3/untitled/testcase.js:34:1)
    at Module._compile (module.js:413:34)
    at Object.Module._extensions..js (module.js:422:10)
    at Module.load (module.js:357:32)
    at Function.Module._load (module.js:314:12)
    at Function.Module.runMain (module.js:447:10)
    at startup (node.js:141:18)
    at node.js:933:3

The only nuisance with that is that it breaks hoisting, unless it would be handled by TypeScript.

[benjamingr]

Promise.coroutine is meant to be called once per function. Calling it per invocation is very slow.