Implement unhandled rejection tracking

[petkaantonov]

Implement unhandled rejection tracking for promises as
specified in https://gist.github.com/benjamingr/0237932cee84712951a2

Fixes #256

Note that I did not implement any default action - so errors are still
swallowed by default and many developers are therefore not going
to discover the hooks. My recommendation would be by default
to log the error as "Potentially unhandled: " + error.stack (and
for example "no stack trace" for non-errors).

These hooks are enough to implement any kind of error handling scheme, including
log-on-gc (needs native module I think).

@domenic , @rvagg , @vkurchatkin , @benjamingr ,@bnoordhuis

[benjamingr]

Awesome! I think this is the least argumentive way to go forward requiring the least changes to core.

(cc @paulirish )

[tellnes]

Why not throw new Error('unexpected PromiseRejectEvent') which is basically what this does?

[petkaantonov]

This throws AssertionError, I think it's an important difference.

[vkurchatkin]

Yeah, asserts are fine when something is not supposed to happen.

[vkurchatkin]

We clearly have a misunderstanding about WeakMap. I think you can achieve the same behaviour with plain Map. Here is diff to illustrate (I was trying to do exactly what you are doing):

diff --git a/src/env-inl.h b/src/env-inl.h
index c5f2328..27e09cd 100644
--- a/src/env-inl.h
+++ b/src/env-inl.h
@@ -331,6 +331,14 @@ inline Environment::IsolateData* Environment::isolate_data() const {
   return isolate_data_;
 }

+inline void Environment::RunAfterLoopCallback() {
+  v8::Handle<v8::Function> callback = this->after_loop_callback();
+
+  if (!callback.IsEmpty()) {
+    callback->Call(this->process_object(), 0, nullptr);
+  }
+}
+
 // this would have been a template function were it not for the fact that g++
 // sometimes fails to resolve it...
 #define THROW_ERROR(fun)                                                      \
diff --git a/src/env.h b/src/env.h
index 4a4eaa3..75f6703 100644
--- a/src/env.h
+++ b/src/env.h
@@ -215,6 +215,7 @@ namespace node {
   V(zero_return_string, "ZERO_RETURN")                                        \

 #define ENVIRONMENT_STRONG_PERSISTENT_PROPERTIES(V)                           \
+  V(after_loop_callback, v8::Function)                                        \
   V(async_hooks_init_function, v8::Function)                                  \
   V(async_hooks_pre_function, v8::Function)                                   \
   V(async_hooks_post_function, v8::Function)                                  \
@@ -398,6 +399,8 @@ class Environment {
   inline bool printed_error() const;
   inline void set_printed_error(bool value);

+  inline void RunAfterLoopCallback();
+
   inline void ThrowError(const char* errmsg);
   inline void ThrowTypeError(const char* errmsg);
   inline void ThrowRangeError(const char* errmsg);
diff --git a/src/node.cc b/src/node.cc
index 990feea..cf8298b 100644
--- a/src/node.cc
+++ b/src/node.cc
@@ -1002,6 +1002,16 @@ void SetupPromises(const FunctionCallbackInfo<Value>& args) {
       FIXED_ONE_BYTE_STRING(args.GetIsolate(), "_setupPromises"));
 }

+void SetAfterLoopCallback(const FunctionCallbackInfo<Value>& args) {
+  Environment* env = Environment::GetCurrent(args);
+
+  if (args[0]->IsFunction()) {
+    env->set_after_loop_callback(args[0].As<Function>());
+  }
+
+}
+
+

 Handle<Value> MakeCallback(Environment* env,
                            Handle<Value> recv,
@@ -2779,6 +2789,8 @@ void SetupProcessObject(Environment* env,
   env->SetMethod(process, "_setupPromises", SetupPromises);
   env->SetMethod(process, "_setupDomainUse", SetupDomainUse);

+  env->SetMethod(process, "_setAfterLoopCallback", SetAfterLoopCallback);
+
   // pre-set _events object for faster emit checks
   process->Set(env->events_string(), Object::New(env->isolate()));
 }
@@ -3710,6 +3722,7 @@ int Start(int argc, char** argv) {
     bool more;
     do {
       more = uv_run(env->event_loop(), UV_RUN_ONCE);
+      env->RunAfterLoopCallback();
       if (more == false) {
         EmitBeforeExit(env);

@@ -3718,6 +3731,7 @@ int Start(int argc, char** argv) {
         more = uv_loop_alive(env->event_loop());
         if (uv_run(env->event_loop(), UV_RUN_NOWAIT) != 0)
           more = true;
+        env->RunAfterLoopCallback();
       }
     } while (more == true);
     code = EmitExit(env);
diff --git a/src/node.js b/src/node.js
index a8278c1..51b26b8 100644
--- a/src/node.js
+++ b/src/node.js
@@ -395,6 +395,7 @@
     // this should be kept in sync with PromiseRejectEvent in v8.h
     var kPromiseRejectWithNoHandler = 0;
     var kPromiseHandlerAddedAfterReject = 1;
+    var pendingRejections = new Map();

     function promiseRejectCallback(event, promise, value) {

@@ -406,19 +407,43 @@

     function promiseRejectWithNoHandlerCallback(promise, value) {
       var rejection = new PromiseRejection(promise, value);
-      process.emit('unhandledPromiseRejection', promise, rejection);
-
-      if (!rejection.isHandled()) {
-        process.nextTick(function() {
-          throw value;
-        });
-      }
+      pendingRejections.set(promise, rejection);
+
+      // process.emit('unhandledPromiseRejection', promise, rejection);
+      //
+      // if (!rejection.isHandled()) {
+      //   process.nextTick(function() {
+      //     throw value;
+      //   });
+      // }
     }

     function promiseHandlerAddedAfterRejectCallback(promise) {
-      process.emit('unhandledPromiseRejectionHandled', promise);
+      var pendingRejection = pendingRejections.get(promise);
+
+      if (pendingRejection) {
+        pendingRejections.delete(promise);
+      } else {
+        process.emit('unhandledPromiseRejectionHandled', promise);
+      }
+
     }

+    process._setAfterLoopCallback(function() {
+
+      for (let rejection of pendingRejections.values()) {
+        process.emit('unhandledPromiseRejection', rejection.promise, rejection);
+
+        if (!rejection.isHandled()) {
+          process.nextTick(function() {
+            throw rejection.value;
+          });
+        }
+      }
+
+      pendingRejections.clear();
+    });
+
     function PromiseRejection(promise, value) {
       this.promise = promise;
       this.value = value;

[vkurchatkin]

An example of nondeterministic behaviour:

process.on('unhandledRejection', function() {
  console.log('unhandledRejection');
});

var p = Promise.reject();

setImmediate(function() {
  var a = Promise.reject();

  process.nextTick(function() {
    a.catch(function(){});

  });
});

Logs unhandledRejection 2 times. Comment out first rejection: logs 0 times

[benjamingr]

@vkurchatkin good example - @petkaantonov why is the wait not promise specific? Is firing one per promise expensive?

[benjamingr]

@vkurchatkin the WeakMap and array are because there are two distinct collections here - one holding the promises to be reported at the next turn as unhandled - it's life duration is one turn and it should not hold references to promises for longer than that. The other is a map of all unhandled rejections so we can report them as handled - this has to retain a reference to these promises for all eternity but it must not hold a strong reference to the promises since that would interfere with GC (if something was GC'd it's impossible for it to be later handled).

If we use a regular map either we don't retain promises long enough or we leak because we keep a reference to them

[vkurchatkin]

The other is a map of all unhandled rejections so we can report them as handled

we don't need this. We have a map, we emit events for every rejection in the map and clear it. After that, if we receive kPromiseHandlerAddedAfterReject and promise is not in the map, we know that the event was emitted already an we need another one (rejectionHandled). No need to store these promises at all

[petkaantonov]

@vkurchatkin using the afterLoopCallback these will have different behavior:

var p = Promise.reject()
setImmediate(function() {
  p.catch(function(){});
});

setImmediate(function() {
  p.catch(function(){});
});
var p = Promise.reject()

It also occasionally causes all the tests to fail.

[domenic]

#758 (comment) is an interesting example. As far as I can tell @petkaantonov is basically following https://gist.github.com/domenic/9b40029f59f29b822f3b#promise-error-handling-hooks-rough-spec-algorithm (with setImmediate = notify-rejected task... not sure why it's setImmediate + process.nextTick though?). So if we want to eliminate that example, which we almost certainly do, then we should probably fix the spec in that case.

[petkaantonov]

That is only because I was using nextTick as a generic micro task scheduler, when I use Promise.resolve().then(fn) as microtask scheduler, it works

[domenic]

@petkaantonov can you help me undesrstand why you do setImmediate + schedule a microtask, instead of just doing the work directly inside setImmediate?

[domenic]

Also if it is necessary you may be able to use V8 natives to do the equivalent semantically without creating two promises: https://code.google.com/p/v8/source/browse/branches/bleeding_edge/src/promise.js#120

[petkaantonov]

So that

var p = Promise.reject()
setImmediate(function() {
  p.catch(function(){});
});

setImmediate(function() {
  p.catch(function(){});
});
var p = Promise.reject()

Give the same result

[petkaantonov]

Basically as soon as you write Promise.reject() v8 calls the rejection hook synchronously, so a setImmediate is synchronously called right as you call Promise.reject() - so this would cause those above snippets to have different result which is very undesirable I think.

[domenic]

That makes sense. However it's kind of a losing game, right? E.g. now you've just pushed off the problem so that

var p = Promise.reject();
setImmediate(function() {
  Promise.resolve().then(function () {
    p.catch(function(){});
  });
});

vs.

setImmediate(function() {
  Promise.resolve().then(function () {
    p.catch(function(){});
  });
});
var p = Promise.reject();

give different results.

[petkaantonov]

Oh right. Well, what I want is basically scheduleMacroTaskAfterAllOtherMacroTasks

[domenic]

Yeah I see. I think we should either do that or we should give up and let it be order-dependent.

[petkaantonov]

I should be able to add internal method that adds to setImmediate's "late queue". (it doesn't exist probably)

[benjamingr]

@petkaantonov what's so bad about a setTimeout with 0 like @vkurchatkin suggested?

[petkaantonov]

@benjamingr Even using setTimeout with 0 this fails:

common.asyncTest(function(done) {
  var e = new Error();
  onUnhandledFail(done);
  setImmediate(function() {
    var a = Promise.reject();
    process.nextTick(function() {
      a.catch(function(){});
    });
  })
});

[benjamingr]

Given that I never care about looking dumb.... @petkaantonov, what about setTimeout(fn, 1) :D? Wouldn't a non-zero value fix it?

[petkaantonov]

That causes this to fail

common.asyncTest(function(done) {
  var e = new Error();
  onUnhandledFail(done);
  var _reject;
  var promise = new Promise(function(_, reject) {
    _reject = reject;
  });
  setImmediate(function() {
    promise.then(assert.fail, function(){});
  });
  _reject(e);
});

FWIW the best behavior I got was using setImmediate with V8 microtask from promise. Any other combination I tried fails in mythical ways, almost as if setImmediate, setTimeout and nextTick were coupled in some strange ways.

[benjamingr]

Right, so a quick recap on where this PR stands.

Open issues with the PR:

• As @vkurchatkin said a WeakMap + array isn't needed - we can do this with an array or a map. @petkaantonov has already started working on implementing it this way.
• As @domenic said, it's probably a good and the easiest thing thing to report after setImmediate (a macrotask). I believe that while this will not have awesome precision and might report false positives when async exception handlers are attached (which is itself very rare in my experience) the alternatives have proven to be inconsistent. So I suggest logging unhandled rejections this way - the added benefit is that we can always improve precision and recall of this at a later PR.

Things that are interesting to talk about as a result of the PR but should not postpone it:

• A default handler to untracked rejections. There are a lot of strong opinions on this and it's a very big issue that can be a breaking change. In my opinion it should be postponed to a future PR
• Discussing how to run the hook with a guarantee a whole macro+micro task has passed - as several people have noted this has proven to be very hard because of how setImmediate and other deferring mechanisms are implemented (namely - things like the fact a nested setImmediate does not act the same as a non-nested one).

[petkaantonov]

Rebased, fixed issues and squashed all commits into one

[vkurchatkin]

is it better than Map?

[benjamingr]

@vkurchatkin not that it should matter that much but it's much faster than a map and the performance is more predictable from what I understand. Especially since all you do to it anyway is just iterate it once.

[vkurchatkin]

I'm worried about splicing

[petkaantonov]

@vkurchatkin yes https://twitter.com/jashkenas/status/563736012313350144/photo/1

[vkurchatkin]

for..of prevents optimizations, but what about forEach?

[petkaantonov]

Yes splicing is slow too (can implement custom splice if you need), but nothing compared to using maps and iterator protocols.

[petkaantonov]

It's not about optimizations but how the iterator protocol is specified - every iteration allocates an object with done and value properties. However forEach could be interesting as V8 shares the iteration object between iterations. But the main reason of using array is that it's going to be small in practice, typically 0 or 2 items.

[vkurchatkin]

see #525. for..of is much slower than iterating manually, though we reused IterationResult objects

[benjamingr]

@petkaantonov I'm not sure what that twit proves or shows. @vkurchatkin said he is worried about the impact of .spliceing for removing from the array.

At the moment deleting from a map does this - removing from an OrderedHashMap which in turn inherits from OrderedHashTable which has a Remove implemented in objects.cc line 16104 calling RemoveEntry in L16207 which puts a hole in the map where the entry was. The crux here is that ECMAScript maps are ordered by insertion order so they have to maintain order anyway - so there is something akin to an array splice going on anyway - even if v8 will improve its implementation.

For sizes this big it shouldn't matter very much anyway since rejections are rare. If we want performance that is at the theoretical bound of a map we can put nulls in the array instead of splicing and skipping them during iteration - like a map does.

[rvagg]

https://jenkins-iojs.nodesource.com/job/iojs+any-pr+multi/193/

[vkurchatkin]

LGTM although I imagine you may have angered the line-length gods

@bnoordhuis would be really unhappy with long lines :)

[benjamingr]

Awesome, great work everyone and especially @petkaantonov and @vkurchatkin - it was a long issue + spec + pr + 300 comment road to cross but I think we learned a lot in the process and the semantics formed quite nicely.

[rvagg]

landed in 872702d

pretty sure @petkaantonov earns a collaborator spot for persisting with this, thanks @petkaantonov and others who contributed!

[rvagg]

It's just occurred to me that this is missing docs, could someone qualified please write some up and submit a PR? would be really good to have that in prior to a release #932 (tomorrow?)

[benjamingr]

Awesome! If my opinion counts I definitely think @petkaantonov deserves a collaborator spot - this and other PRs show that he has a lot to offer to io.js in terms of APIhelp and performance.

@rvagg already made a docs PR :) (Whoops, I pulled against the wrong fork, here it is now #946 )

[tjconcept]

Amazing work being done. This is Open Source.

[benjamingr]

Politely pinging parties involved in this to invite them to participate in https://github.com/nodejs/promises