Refine monitor reporting API

[briancavalier]

In 3.0, the monitor is getting a total rewrite. This is a good time to figure out what the right API would be to make it easy for developers to hook their own reporter into the monitor. See this discussion over in #254 for a start.

[AriaMinaei]

PromiseMonitor being a class just made everything a whole lot easier!

I'd like to share a my half-baked thoughts:

First, about this code and the stack trace below:

wn().then ->
   wn().then ->
      a = c

I think this error is too long for such a short piece of code. Are there use-cases for seeing lines like Scheduler._drainQueue and Handler.FulfilledHandler.when in the trace?

Noting that it's hard to safely omit these lines in an external package like PrettyMonitor, one idea would be to filter them out by default inside PromiseMonitor, and adding an option to disable the filtering.

Also, if PromiseMonitor could accept either a function or an object with a log() property, then we could write:

new PromiseMonitor(new PrettyMonitor())

... instead of:

new PromiseMonitor((new PrettyMonitor).log)

... but that's just a taste thing :)

[briancavalier]

Hey @AriaMinaei. Thanks for trying it out!

Yeah, currently the filtering is done in simpleReporter, which can be configured with a stack filtering RegExp. It wasn't clear to me what the right level of abstraction is here: I can imagine some people wanting access to complete stack traces when writing a custom reporter, but simple custom reporters probably just want the more interesting bits, like you said.

Maybe there should be a module that custom reporters can use to do filtering? ie instead of building the filtering directly into either PromiseMonitor or simpleReporter, externalize it so reporter authors can decide? Or maybe a wrapper that filters before delegating to a custom reporter, something like:

new PromiseMonitor(filteringReporter(myStackFilter, new PrettyMonitor())));

What do you think about one of those approaches?

Accepting either an object or a function is doable. Or maybe I'll just go with an object ... either way, supporting an object should be no problem.

[briancavalier]

I just switched to an object with a report method for the reporter in the dev branch :)

[AriaMinaei]

... currently the filtering is done in simpleReporter, which can be configured with a stack filtering RegExp ... Maybe there should be a module that custom reporters can use to do filtering?

Well, that would make everything very flexible, but perhaps a bit hard to use.

A user that just switched from callbacks to promises simply shouldn't have to worry about all that stuff. They expect things to just work. They don't even suppose error reporting might be an issue. And we can make sure things work the way they expect — have unhandled rejections show up like any other error, clean and readable, no extra stuff.

And should they prefer to see the extra stuff, they will have the choice.

instead of building the filtering directly into either PromiseMonitor or simpleReporter, externalize it so reporter authors can decide?

I know, doing the stack filtering inside PromiseMonitor doesn't sound good from an engineering point of view, but it could make things a bit simpler. Consider this snippet: (and forgive my coffeescript :) )

monitor = new PromiseMonitor (trace) ->

   console.log(trace) # the trace is filtered by default

   # or:
   prettyMonitor.log(trace)

# to turn it off:
monitor.setStackFiltering(off)

# to customize it:
monitor.setStackFilter (trace) ->

   # return a custom filtered trace

# when using when/monitor/console:
consoleMonitor = require 'when/monitor/console'
consoleMonitor.promiseMonitor.setStackFiltering(off)

# when using PrettyMonitor:
monitor = new PromiseMonitor(new PrettyMonitor)
monitor.setStackFiltering(off)

Although, these functions could probably have better names than the ones I chose :)

---

By the way, I'm not sure plucking the trace lines that belong to when is completely doable with just regular expressions. We can't rely on file paths, because it's unstable, and what if the script is bundled with something like browserify?

[briancavalier]

Good suggestion. Giving PromiseMonitor a configurable filter seems just fine. I like that it separates filtering from logging/formatting. I'll look into doing that shortly after 3.0 is out the door.

By the way, I'm not sure plucking the trace lines that belong to when is completely doable with just regular expressions

Agreed. A regex isn't good enough for all cases. In 2.x it was a function, so it was more flexible, but in general, it's a non-trivial problem for the reasons you mentioned. I just needed to get something simple done for 3.0, so I went with a regex. I think going back to a function after 3.0 is the right thing.

[briancavalier]

@AriaMinaei I've started to dig into this in the dev branch. Lots of improvements in f7f4bbe and 58d1505. Now, PromiseMonitor does all of the filtering and stitching, and the reporter can be as simple as an object with a single method: log(arrayOfPromiseTraces). Where each item in arrayOfPromiseTraces is a long stack trace (which is itself an array of stack frame strings). That makes ConsoleReporter's log() method quite simple--in fact, ConsoleReporter itself is much simpler now (with the exception of the console capability detection at the bottom).

The filtering is now done based on a combination of constructor and function names, but also has fallbacks to file paths. That seems to do an excellent job while using separate modules, and also does a pretty good job when using a combined build, like the es6-shim or the full browserified version. There's def more we can do there, but I'm pretty satisfied with it for now, esp since it only took a few simple additions to the regex.

Anyway, do you think this new reporter API, { log: function(arrayOfPromiseTraces) } will work for you?

Another option is { log: function(oneLongTraceAtATime) }. The reason I didn't go with that, is that some reporters may want to display a message before/after all of the traces are logged, or use console.groupStart/groupEnd (like ConsoleReporter does).

Let me know what you think. I'm really looking forward having PrettyMonitor work with when 3.x!

[AriaMinaei]

The code reads just beautifully :)

Anyway, I have to go, but I just wanted to do a quick test without PrettyMonitor, so here goes:

PromiseMonitor = require 'when/monitor/PromiseMonitor'
PrettyError = require 'pretty-error'
wn = require 'when'

prettyError = new PrettyError

logger = log: (traces) ->

    console.log prettyError.render

        kind: 'Rejection'

        message: traces[0][0]

        stack: traces[0].splice(1, traces[0].length).join '\n'

promiseMonitor = new PromiseMonitor logger

console.promiseMonitor = promiseMonitor

wn().then ->

    wn().then ->

        a = b

and here is the result:

Awesome!

[briancavalier]

That is sweeeet :+1:

[jescalan]

Looks super nice @AriaMinaei!

[AriaMinaei]

@jenius: oh it was all @briancavalier's work, kudos to him, I didn't have to change any of my code :)

@briancavalier, I'm ready to update PrettyMonitor. Please let me know when you think I should.

do you think this new reporter API, { log: function(arrayOfPromiseTraces) } will work for you? ... The reason I didn't go with that, is that some reporters may want to display a message before/after all of the traces are logged

Yeah, I agree. arrayOfPromiseTraces is more useful. I will update PrettyMonitor to use this feature!

---

I have a few suggestions I'd like to add:

First, reading defaultStackFilter regexp:

/(node|module|timers)\.js:|when(\/(lib|monitor|es6-shim)\/|\.js)|(new\sPromise)\b|(\b(PromiseMonitor|ConsoleReporter|Scheduler|RunHandlerTask|ProgressTask|Promise|.*Handler)\.[\w_]\w\w+\b)|\b(tryCatch\w+|getHandler\w*)\b/i

I think this might return false positives. Words like 'Scheduler' and 'ProgressTask' may not be unique to when.js. I'm developing a package (theatre.js) that's gonna have a class named 'Scheduler', for example.

---

It would be really great if setting up a custom monitor was as easy as this:

PromiseMonitor = require 'when/monitor/PromiseMonitor'
PrettyMonitor = require 'pretty-monitor'
new PromiseMonitor(new PrettyMonitor())

That would require one thing, though. If PrettyMonitor also knew about PromiseMonitor, it could have the ability to configure it. For example, since it's always in the nodejs environment, it could disable the filtering and use it's own filters, like it's skipPackage() and skipNodeFiles() methods. You know, so that the user doesn't have to configure stack filtering in two different places.

Anyway, if you think that's a good idea, we could add this line to PromiseMonitor:

if typeof reporter.setPromiseMonitor is 'function'

    reporter.setPromiseMonitor this

And it would be great if we could just skip this line:

console.promiseMonitor = promiseMonitor

... which would be less boilerplate code. Maybe PromiseMonitor can somehow introduce itself to the core promise engine upon instantiation. Just a thought.

---

It would also be nice if stackJumpSeparator in PromiseMonitor was configurable. Maybe it could be a class member or something.

Anyway, sorry if I'm making too many suggestions. I just really like this project :)

[briancavalier]

I'm ready to update PrettyMonitor. Please let me know when you think I should.

I'm working on getting 3.1 ready for release asap (shooting for Tuesday). If PrettyMonitor already works with the dev branch, we could release roughly simultaneously :)

I think this might return false positives. Words like 'Scheduler' and 'ProgressTask' may not be unique to when.js. I'm developing a package (theatre.js) that's gonna have a class named 'Scheduler', for example.

Yeah, it will. I honestly think the only way to get it right via regex is to name all of when's internal functions using some bizarre naming scheme like when$Scheduler and when$Scheduler$enqueue. But I agree making it configurable is the best option. In my sandbox, it's a configurable property.

You know, so that the user doesn't have to configure stack filtering in two different places.

Right, def want to avoid that if we can. Another option would be for PromiseMonitor to pull properties from the reporter. It's a tradeoff: slightly less flexible, but breaks the circular dep.

introduce itself to the core promise engine upon instantiation

Seems that either one has to be told about the other, or they have to rendezvous on some shared state, like console. One nice thing about rendezvousing on console is that there is no direct dependency between PromiseMonitor and the rest of when, which means you can browserify each independently very easily.

One similar approach that would work and maintain the separation is to make people set a property:

var when = require('when');
when.promiseMonitor = require('when/monitor/console');

Instead of the "magical" require we have now:

require('when/monitor/console');
var when = require('when');

Or perhaps simply move the console.promiseMonitor assignment into a convenience method on PromiseMonitor instances. Not really much different, but maybe easier on the eyes.

promiseMonitor.activate();

It would also be nice if stackJumpSeparator in PromiseMonitor was configurable. Maybe it could be a class member or something.

Yep, agreed. it's a configurable property in my sandbox :)

[AriaMinaei]

I'm working on getting 3.1 ready for release asap (shooting for Tuesday). If PrettyMonitor already works with the dev branch, we could release roughly simultaneously :)

Sounds good! I'm gonna simplify PrettyMonitor quite a bit, now that PromiseMonitor is handling most of the tasks, so I'll keep you posted here.

[AriaMinaei]

Okay, I pushed a commit, which you can test like this:

PromiseMonitor = require 'when/monitor/PromiseMonitor'
PrettyMonitor = require 'pretty-monitor'
wn = require 'when'

console.promiseMonitor = new PromiseMonitor new PrettyMonitor

wn().then ->

    wn().then ->

        a = b

Here is the result:

Anyway, I configured PrettyError not to skip any trace lines, so please take a look and see if the result looks right. I'm particularly concerned about the lines pointing to makePromise.js. Should we skip them?

The "from execution context" lines could also be simplified, but PrettyMonitor doesn't have access to PromiseMonitor, so I'm skipping that for now.

Anyway, looking at the result, I think we can make it look less cluttered, so I'm waiting for your feedback.

[briancavalier]

@AriaMinaei Cool. I'm very close on 3.1 as well ... basically final testing.

Hmmm, I thought PromiseMonitor would filter out those makePromise lines before they got to PrettyMonitor. Here's a similar test without PrettyMonitor:

[promises] Unhandled rejections: 1
ReferenceError: b is not defined
    at /Users/brian/Projects/cujojs/when/experiments/test.js:6:7
from execution context:
    at /Users/brian/Projects/cujojs/when/experiments/test.js:5:16
from execution context:
    at /Users/brian/Projects/cujojs/when/experiments/test.js:5:9
from execution context:
    at Object.<anonymous> (/Users/brian/Projects/cujojs/when/experiments/test.js:4:1)

Ah, perhaps PrettyMonitor is rewriting the file path before PromiseMonitor can filter the stack, ie via v8's Error.formatStackTrace? If that's the case, then we could either try to make PromiseMonitor's regex just slightly better (not a long term solution, I know, but maybe ok for 3.1), or have PrettyMonitor filter any lines referring to files inside [when]/lib?

As for "from execution context:", the idea is that there needs to be some indication to the developer that this is no ordinary stack trace, but rather an asynchronous tick-spanning trace that "jumps around". I'm all for simplifying it, if that can remain obvious.

To do that, PromiseMonitor needs to put some sort of "marker" in the long stack traces where the jumps are. One option would be to put a more generic marker in, like '--------', and maybe PrettyMonitor and when's simple ConsolerReporter could both handle those however they want. For example, ConsoleReporter could replace them with "from execution context:", and PrettyMonitor could do something, well, prettier :) like reducing the line spacing, dimming them, and outdenting them. Anyway, using a generic marker could give you more control.

Another option, like you mentioned before is to allow configuration to flow from PrettyMonitor back to PromiseMonitor either via some API, like having PromiseMonitor pass itself to a configure method on the reporter instance it's given, or by having PromiseMonitor pull some property settings from the reporter. The former seems a bit more flexible.

What do you think?

[AriaMinaei]

perhaps PrettyMonitor is rewriting the file path before PromiseMonitor can filter the stack, ie via v8's Error.formatStackTrace?

I actually see those lines with when/monitor/console too, so, I don't think that's the case.

... or have PrettyMonitor filter any lines referring to files inside [when]/lib?

That's easily doable, but then PrettyMonitor would be meddling in PromiseMonitor's work, and soon things could get less manageable. For example, if I removed 'makePromise.js:97 reject' from the trace, then I would also have to remove the 'from execution context' line that comes before it. Also, since we need the same simple trace lines in the browsers too, it would be better to keep this filter in one place, imho.

As for "from execution context:", the idea is that there needs to be some indication to the developer that this is no ordinary stack trace, but rather an asynchronous tick-spanning trace that "jumps around". I'm all for simplifying it, if that can remain obvious.

Yeah I actually meant that for PrettyMonitor. It already looks quite simple and obvious in when/monitor/console. I was too thinking of complimenting it with some visual indicator in PrettyMonitor. But to do that, it would require PrettyMonitor to parse the trace, look for 'from execution context' which is a term that the user might configure differently, or it might not always be the default term in future versions of PromiseMonitor, so PrettyMonitor has to read it from PromiseMonitor.

Another option, like you mentioned before is to allow configuration to flow from PrettyMonitor back to PromiseMonitor either via some API, like having PromiseMonitor pass itself to a configure method on the reporter instance it's given, or by having PromiseMonitor pull some property settings from the reporter. The former seems a bit more flexible.

The first method sounds better to me. It's very flexible, solves more than one problem, and I don't think the circular dependency it creates could get out of hand, since it's in a simple, well-isolated part of the code. The flexibility here outweighs the risk, imho.

Or perhaps simply move the console.promiseMonitor assignment into a convenience method on PromiseMonitor instances. Not really much different, but maybe easier on the eyes.

I'd humbly suggest to go all the way for simplicity. In my head, a PromiseMonitor is always active, unless explicitly deactivated. (Which means we could have more than one active PromiseMonitor, which might be useful if we're both logging to some API and the terminal.)

[AriaMinaei]

Btw, I don't know why GitHub is formatting my last reply like that :)

[briancavalier]

I actually see those lines with when/monitor/console too, so, I don't think that's the case.

Strange. I don't see them. See the example in my previous comment. It's from a test that is exactly like your previous example:

require('../monitor/console');
var when = require('../when');

when().then(function() {
    return when().then(function() {
        a = b;
    });
});

Any idea what might be going on? I don't get bracketed path segments in any stack traces when only using ConsoleReporter, that's why I wondered if Error.formatStackTrace was in play somehow.

The first method sounds better to me

Ok, how about something like:

function PromiseMonitor(reporter) {
    // ... other stuff .. and then
    if(typeof reporter.configure === 'function') {
        reporter.configure(this);
    }
}

Does that look sufficient? PrettyMonitor could provide a configure method and off we go.

In my head, a PromiseMonitor is always active, unless explicitly deactivated

This would be great, but it's a significant perf hit. Right now it's 5-10x CPU and about 5x memory due to the extra bookkeeping that the promise machinery has to do. I have some ideas on how we can bring that down, but probably won't have time to implement anything until a later 3.x. For example, we can do short/simple stack traces instead of full async stack traces for unhandled rejections, and that'll help a lot. Full async stack traces could be an option. So yeah, it's a great goal for sure.

[briancavalier]

@AriaMinaei 3.1 is ready for release. Let me know what you think about the configure API. If you're cool with that, I'll get it into 3.1. If you think we need to discuss more, that's cool, too--I'll just release 3.1 and we can target 3.1.1.

[AriaMinaei]

Any idea what might be going on? I don't get bracketed path segments in any stack traces when only using ConsoleReporter, that's why I wondered if Error.formatStackTrace was in play somehow.

Yeah, let me see if I can come up with steps to reproduce this error.

Let me know what you think about the configure API. If you're cool with that, I'll get it into 3.1. If you think we need to discuss more, that's cool, too--I'll just release 3.1 and we can target 3.1.1.

configure will work. I'd personally prefer setPromiseMonitor but whatever works for your style of coding :)

On Apr 2, 2014, at 6:26 AM, Brian Cavalier notifications@github.com wrote:

@AriaMinaei 3.1 is ready for release. Let me know what you think about the configure API. If you're cool with that, I'll get it into 3.1. If you think we need to discuss more, that's cool, too--I'll just release 3.1 and we can target 3.1.1.

— Reply to this email directly or view it on GitHub.

[briancavalier]

Thanks for looking into that error. I think I'll go with configure. In my head, the purpose of the method is to provide an opportunity to configure the PromiseMonitor, not necessarily to hold onto it as a property, so I don't want to make that implication. If we learn, through usage, that configure was a bad choice, I don't mind changing it (in lockstep with PrettyMonitor, of course), since there aren't a lot of people writing PromiseMonitor reporters!

[AriaMinaei]

the purpose of the method is to provide an opportunity to configure the PromiseMonitor, not necessarily to hold onto it as a property, so I don't want to make that implication

Nice point! I agree.

How about configurePromiseMonitor? You know, to make sure it doesn't sound like it configures PrettyMonitor itself.

[briancavalier]

How about configurePromiseMonitor?

Nice, that's very clear. Let's go with it.

On a slightly related note, we seem to be having an issue with saucelabs browser testing right now. I thought a code change broke them, but I've taken a known-good previous commit (which had passed all saucelabs tests) and created a branch, and run that through sauce, and it also fails. All node-based tests pass locally and on travis, too. So, we're blocked on releasing 3.1 until we can figure out what the heck is going on. :(

I'll keep you posted.

[AriaMinaei]

Btw, do you think it's a good idea if I bumped PrettyMonitor's version to match when.js's for clarity?

[briancavalier]

Yeah, I think bumping PrettyMonitor to 0.3.0 to signify when.js 3.x compat sounds good.

Trying to match versions exactly (ie "3.1.0") will probably be a hassle. I'm thinking that the 3.x line will move through versions fairly quickly, at least for for a while--so many ideas for this new architecture!

[AriaMinaei]

I thought PromiseMonitor would filter out those makePromise lines before they got to PrettyMonitor.

Uh, it was nothing, just backslashes in windows path. Anyway, this is going to be the world's smallest pull request :)

290

[AriaMinaei]

Okay, PrettyMonitor seems to be ready for 3.1. I pushed some changes to github. I'll tag and publish when 3.1 is out.

[briancavalier]

Oh ha! Great catch on the windows slashes. Thanks for he PR. I'll merge it shortly.

I'm still trying to figure out why our sauce labs tests are all timing out :( I may just have to bite the bullet and run all the browser tests by hand for this release, ugh. I've already confirmed with several browsers that they pass, but I'll sleep better knowing we have total coverage.

[briancavalier]

PromiseMonitor now calls reporter.configurePromiseMonitor if it exists. Have at it! :)

[briancavalier]

I just updated the docs, too. PrettyMonitor compatibility ftw.

I ran all the sauce browser tests manually (ugh!) last night and everything passes, so I'm gonna release 3.1.0 today. Yay!

[briancavalier]

Since this issue has gotten quite long, I'm gonna close it. If there's more to do (I'm sure we'll think of things), we can open new issues for those, specifically.

[AriaMinaei]

Great job with the release (^_^)b

I think it was absolutely worth the effort. Thanks to PromiseMonitor, when promises are now as debuggable as normal js, maybe even better.

Btw, I just pushed PrettyMonitor 0.3!

[briancavalier]

Yay, PrettyMonitor 0.3! Thank you for the awesome collaboration--the way open source should be! I'm sure we'll find ways to keep it going :)

[AriaMinaei]

Absolutely :)