Preserve stack frames to show where event came from

[danielcompton]

The re-frame router uses an FSM to process events, and puts events in a queue to be processed. This has many advantages, but one of the disadvantages is that you lose the context for where the event was originally called from. For example:

Here we can see the stack trace that led to the error, but it stops at the onmessage trigger, and we don't know which part of our code called the dispatch that led to it. It would be great if we could keep stack frames from the dispatch call around.

https://datahero.com/blog/2014/05/22/node-js-preserving-data-across-async-callbacks/ https://bugs.chromium.org/p/chromium/issues/detail?id=332624

[mike-thompson-day8]

As a solution, I'm wondering if you could write your own function called, say, emit and use it in place of dispatch everywhere. emit would look something like this:

(defn emit 
   [event-vec]
   (when ^boolean js/goog.DEBUG console.trace((str v))
   (re-frame/dispatch event-vec))

The 2nd line of the consoled stack would be the point where the emit happened. The first line would be the emit function itself

Or go to the effort of writing emit as a macro.

Or, if there is enough interest, we could think about stitching this into dispatch itself. But I do prefer layers.

[danielcompton]

Here's another example where the stack trace tells you almost nothing:

[mike-thompson-day8]

Via slack discussion, @darwin introduced me to a sneaky idea which I'll note here so it isn't forgotten:

1. Create a macro called say dispatch2
2. Within this macro, create an anonymous function which wraps console.log
3. Attach this anonymous function to the event's metadata, perhaps using the :logger key.
4. When later it comes time to report what event is being processed, use this :logger obtained from the event itself.

As a result the log message produced will appear to come from the place where the anonymous function itself was defined, which will be the point of the dispatch itself.

[mike-thompson-day8]

So this ticket is about remembering where a dispatch happens. If there are problems in the handling of that event (an exception?), it is useful to show BOTH why the handler blew up AND where the event came from - the dispatch point. The async nature of event handling means stack traces don't show disptach point, and instead show the FSM scheduling mechanism.

So, my cunning plan was to capture the stack in dispatch and attach it as meta-data to the event being dispatched. Later, if ever there was a problem, this stack could be printed, showing from wence the event came. Easy, right? No need for macros. Nice solution!!

Except, except ... every effort I've made has foundered on the rocks of source-maps. It is easy to capture the stack in dispatch but getting a source-mapped version of the stack for later use is ... infuriatingly unreliable.

For the record, capturing the stack in dispatch is easy:

(let [ stack (.-stack (js/Error.))]

stack ends up being a string. "Error:\n ..... ". That first "Error" line needs to be trimmed away. And the reported stack includes dispatch as the top stack-frame , so ideally we'd trim that away as well, but at that point we have the true dispatch point. Probably good enough.

The trimmed stack can then be added as metadata to the queued event in here: https://github.com/Day8/re-frame/blob/3246265483016b2986baa81fbfd11ef4acb8a7b9/src/re_frame/router.cljs#L208

(enqueue event-queue (with-meta event-v  {:stack stack}))

But...

That stack has a nasty habit of not being source-mapped when later printed. And I can't for the life of me figure out why. Sometimes it works, sometimes it doesn't. There is something really fundamental I'm missing. (For a while, I assumed it was dependent on the browser actually loading and interpreting the sourcemap files, but that theory didn't seem to hold up).

Just. Can't. Get. It. To. Work. Damnit. I'm giving up in frustration.

Does anyone else have experience with this kind of thing? Any insights?

The test is really simple - put a (.log js/console (some-> event-v meta :stack)) in here (do you see source-mapped stacks or js stacks): https://github.com/Day8/re-frame/blob/3246265483016b2986baa81fbfd11ef4acb8a7b9/src/re_frame/router.cljs#L147

[darwin]

I have some theory: 1, (.-stack (js/Error.)) is never source mapped

2. Chrome DevTools can sometimes translate stack traces to source mapped stack traces during console printing (probably based on some heuristics, depending on DevTools' source-maps subsystem state, on best-effort basis)

I'm pretty sure about point 1 because they cannot break ECMAScript specs and break old code.

AFAIK source maps subsystem in DevTools is pretty complex async code. So it might just happen that they don't translate stack traces in cases when source-maps are not loaded yet (and such translation might not even trigger source map fetching). I could investigate and explain it exactly by reading their implementation.

[mike-thompson-day8]

Note to self: https://github.com/v8/v8/wiki/Stack-Trace-API

[mike-thompson-day8]

Further note, look at what @darwin has done: https://github.com/binaryage/cljs-devtools/commit/86dbbbbeca5725547ead2f7b852743a7176413f7

[danielcompton]

From Clojurians Slack by @darwin

The trick is to replace goog.async.nextTick with a promise-based implementation. ES6 promises participate in Chrome DevTools “async” feature. it is not super useful ATM, because maxAsyncStackChainDepth is currently hard-coded in DevTools and set to only 4, which is not enough for more complex core.async code: https://github.com/binaryage/dirac/blob/devtools/front_end/sdk/DebuggerModel.js#L200 but in Dirac I can lift that number and maybe walk the call stack in a better way, so loops won’t create long stack traces

[darwin]

The ball is on their side now: https://bugs.chromium.org/p/chromium/issues/detail?id=622506

I cannot solve this in Dirac ATM.

[stumitchell]

Right I have done some investigation and there seem to be a couple of things happening.

1. (.-stack (js/Error.)) is never source mapped
2. Chrome devtools does seem to translate links that are printed to console through LinkifyStackTrace
3. This seems to never be called when less than half of the stack does not have a source map and instead linkifyStringAsFragment is used. I can't seem to find where this decision is made however. @darwin would you be able to look into this and maybe create an issue on devtools?

This bites re-frame in the ass as dispatches from view code tend to be only a couple of frames deep from react (which is not mapped). In the meantime as a stopgap I have removed the react lines from the stack trace and passed this through.

[danielcompton]

In action here: https://github.com/binaryage/cljs-oops/blob/61416373ff8415410c52de1603df76375c848299/src/lib/oops/core.clj#L256

[dijonkitchen]

Any updates or should it be closed?

[mike-thompson-day8]

@dijonkitchen please stop doing this. If there were updates they'd already be in here. So all you are doing is creating noise which is unhelpful and annoying. Instead, feel free to carefully investigate this issue and supply a PR.

[dijonkitchen]

Gotcha, just trying to make sure open issues are active or closed.

[superstructor]

So this issue has taken a few twists and turns, but it is essentially about knowing from whence an event originates - the source code coordinates. I’ve asked around a few re-frame regulars and they don’t feel this is a strong requirement anymore. At best they say “I guess it might be nice to have, maybe” but with no strength.

So, I’m going to close this issue.

However, before I do, I’ll note here an approach that @mike-thompson-day8 tells me he considered at one point (he is a coworker), so that this information is retained, should this issue ever come back to life and become more pressing again.

If ever this was to be done:

• We’d need to change the event queue to be a vector of maps, not just a vector of events, as it is currently.
• Each map in this vector would have to capture not only the event, but the source code coordinates for its dispatch
• We could then change dispatch so that its argument could be either the event (as it is now) or a full map with source code coordinates, etc. (Ie. I wouldn’t attach source code coordinates to the event as meta data, which was proposed at one point)
• Then I’d add an “emit” macro as an alternative to dispatch which programmers would use when they cared to capture source code coordinates. A macro, of course, has the ability to know source code coordinates. And this “emit” could then call dispatch with a map.
• Open question: what to do about effects like “:dispatch” and “:dispatch-later” etc? They shouldn’t record source code coordinates, they should instead record the event which triggered them.
• Open question: how would this information be logged and, later, shown in re-frame-10x

[superstructor]

There was a subsequent discussion on Clojurians Slack between @p-himik @kennyjwilli and @mike-thompson-day8 of which some interesting notes are:

• If there is a compelling use case for re-opening this feature, please make it on this issue. We will review. Comments are still open.

• Keeping backwards compatibility of the event queue (i.e. the vectors) might be worthwhile. Although an internal impl detail, some things like re-frisk might use it. Meta vs data structure change was tabled as an open question.

• Re :dispatch and :dispatch-later the proposal is that an event will now be queued as map of values. Each map in the queue could have a string :source field which EITHER indicates the source code coordinates or it could say "dispatched as an effect when processing event [:id arg1]". Because there would be no source code coordinates, no need for macro magic. You are just getting the event which triggered the :dispatch effect. But these are just ideas at this point.