BUG: Try-catches around callback execution #139

brianreavis · 2014-10-01T00:34:06Z

It is a really bad practice to throw exceptions inside of async code and right now node-neo4j is littered with this. Even worse, there are try/catches around where user callbacks are executed. Can both of these things be fixed? (Edit: Not the problem because of code transformation through streamline) I would offer to refactor, but it's in CoffeeScript (another discussion).

Why is it bad? It makes debugging of exceptions completely unrelated to node-neo4j nearly impossible (just spent an hour doing it). For example, here is a stack trace:

TypeError: undefined is not a function
    at /var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:169:5
    at Object.__g.trampoline.flush (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:23:29)
    at Request.___ [as _callback] (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:120:61)
    at Request.self.callback (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:129:22)
    at Request.EventEmitter.emit (events.js:98:17)
    at Request.<anonymous> (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:873:14)
    at Request.EventEmitter.emit (events.js:117:20)
    at IncomingMessage.<anonymous> (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:824:12)
    at IncomingMessage.EventEmitter.emit (events.js:117:20)
    at _stream_readable.js:920:16

The cause: an undefined function elsewhere in the application.

Here's a simplified scenario:

var done = function() {
    var x = a; // "a" not defined (throws)
};

neo4j.query('somequery', {}, function(err, results) { done(); });

In this example, the TypeError gets caught by neo4j and fails erratically with a stack trace like above.

The text was updated successfully, but these errors were encountered:

aseemk · 2014-10-01T00:48:38Z

Hold your horses, my friend! =)

This code is written in Streamline.js syntax (as mentioned in the readme):

https://github.com/Sage/streamlinejs

Streamline is a tool whose purpose is to let you write async JS as if it were synchronous — allowing you to use the full breadth of JS language features, including try-catch and throw.

(Those two, for example, get compiled to if (err) ... and callback(err) respectively.)

IOW, this library is explicitly designed to do error handling correctly, and AFAIK, it does. If you've encountered a case where it doesn't, that's definitely a bug by oversight, not behavior by design.

In the example you give, for instance, when I run it locally, the stack trace seems fine:

$ node foo.js 

ReferenceError: a is not defined
  at done (/Users/aseemk/Projects/Node/neo4j/foo.js:5:13)
  at /Users/aseemk/Projects/Node/neo4j/foo.js:8:55
  at __$GraphDatabase_prototype_query__20 (/Users/aseemk/Projects/Node/neo4j/lib/GraphDatabase._coffee <generated>:942:24)
  at /Users/aseemk/Projects/Node/neo4j/node_modules/streamline/lib/callbacks/runtime.js:153:5
  ...

I'm really sorry you ran into this issue and had to sink an hour into debugging it. Is the example you gave representative of what you ran into? Or was it more complex than that?

brianreavis · 2014-10-01T01:16:45Z

Perhaps I'm mischaracterizing the problem, but can you explain what's going in / causing that gnarly stacktrace? You're right, my simplified example doesn't seem to reproduce the problem. Regardless, after using node-neo4j, I reach a point in the application where if I run:

console.log(typeof undefinedfunction); // prints out "undefined"
undefinedfunction();

It will throw with a stacktrace like before:

TypeError: undefined is not a function
    at /var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:169:5
    at Object.__g.trampoline.flush (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:23:29)
    at Request.___ [as _callback] (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:120:61)
    at Request.self.callback (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:129:22)
    at Request.EventEmitter.emit (events.js:98:17)
    at Request.<anonymous> (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:873:14)
    at Request.EventEmitter.emit (events.js:117:20)
    at IncomingMessage.<anonymous> (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:824:12)
    at IncomingMessage.EventEmitter.emit (events.js:117:20)
    at _stream_readable.js:920:16

If I comment out the line at fault,

console.log(typeof undefinedfunction); // prints out "undefined"
// undefinedfunction();

The error disappears.

Something, somewhere is getting caught incorrectly by streamline / node-neo4j. I'll dig into it more and see what I can find.

aseemk · 2014-10-01T01:20:13Z

I agree that there's a bug with the stack trace — the first line of the stack trace should point to your code, not node-neo4j's. Just to confirm, is that the crux of the issue to you too?

Off the top of my head, I don't know what would cause that. I'm doing some playing around with code and can't reproduce that either.

Could you perhaps share some more of your real code that's hitting this?

brianreavis · 2014-10-01T01:37:39Z

Yeah, that's the crux – the library shouldn't have any influence once it has passed off control. Here is something small that reproduces the same exception:

neo4j.query('MATCH a->[rel]->b', {}, function() {
    neo4j.query('MATCH a->[rel]->b', {}, function() {
        console.log('done');
    });
    var a = somethingundefined;
});

TypeError: undefined is not a function
    at /var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:169:5
    at Object.__g.trampoline.flush (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:23:29)
    at Request.___ [as _callback] (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:120:61)
    at Request.self.callback (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:129:22)
    at Request.EventEmitter.emit (events.js:98:17)
    at Request.<anonymous> (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:873:14)
    at Request.EventEmitter.emit (events.js:117:20)
    at IncomingMessage.<anonymous> (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:824:12)
    at IncomingMessage.EventEmitter.emit (events.js:117:20)
    at _stream_readable.js:920:16

aseemk · 2014-10-01T01:40:35Z

Hmm... still works fine for me:

$ node foo.js 

ReferenceError: somethingundefined is not defined
  at /Users/aseemk/Projects/Node/test/foo.js:8:13
  at __$GraphDatabase_prototype_query__20 (/Users/aseemk/Projects/Node/neo4j/lib/GraphDatabase._coffee <generated>:942:24)
  at /Users/aseemk/Projects/Node/neo4j/node_modules/streamline/lib/callbacks/runtime.js:153:5
  ...

Question: can you share the output of running this?

cd node_modules/neo4j
npm ls

brianreavis · 2014-10-01T01:54:31Z

neo4j@1.1.0 /var/www/naturalatlas.com/shared/node_modules/neo4j
├── http-status@0.1.8
├─┬ request@2.27.0
│ ├── aws-sign@0.3.0
│ ├── cookie-jar@0.3.0
│ ├── forever-agent@0.5.2
│ ├─┬ form-data@0.1.4
│ │ ├── UNMET DEPENDENCY async ~0.9.0
│ │ └─┬ combined-stream@0.0.5
│ │   └── delayed-stream@0.0.5
│ ├─┬ hawk@1.0.0
│ │ ├── boom@0.4.2
│ │ ├── cryptiles@0.2.2
│ │ ├── hoek@0.9.1
│ │ └── sntp@0.2.4
│ ├─┬ http-signature@0.10.0
│ │ ├── asn1@0.1.11
│ │ ├── assert-plus@0.1.2
│ │ └── ctype@0.5.2
│ ├── json-stringify-safe@5.0.0
│ ├── mime@1.2.11
│ ├── UNMET DEPENDENCY node-uuid ~1.4.0
│ ├── oauth-sign@0.3.0
│ ├── qs@0.6.6
│ └── tunnel-agent@0.3.0
└─┬ streamline@0.10.15
  ├── fibers@1.0.2
  ├── galaxy@0.1.11
  └─┬ source-map@0.1.39
    └── amdefine@0.1.0

npm ERR! missing: node-uuid@~1.4.0, required by request@2.27.0
npm ERR! missing: async@~0.9.0, required by form-data@0.1.4
npm ERR! not ok code 0

On node v0.10.26 w/async@0.9.0 and node-uuid@1.4.1 (a level up)

aseemk · 2014-10-01T02:00:49Z

Hmm, your dependencies look good.

One thing we could try is manually recompiling your node-neo4j with the latest Streamline, as I see that the compiled version in npm was from a reasonably older version of Streamline now.

# within node_modules/neo4j still:
npm run clean
npm run build

Do things work for you then? If so, great that we found the cause — I'll re-publish to npm with a re-compile to make sure others don't run into this too.

brianreavis · 2014-10-01T02:13:06Z

www-data@naturalatlas:/var/www/naturalatlas.com/current/node_modules/neo4j$ npm run clean

> neo4j@1.1.0 clean /var/www/naturalatlas.com/shared/node_modules/neo4j
> rm -f lib/*.{js,map}

www-data@naturalatlas:/var/www/naturalatlas.com/current/node_modules/neo4j$ npm run build

> neo4j@1.1.0 build /var/www/naturalatlas.com/shared/node_modules/neo4j
> coffee -m -c lib/ && _coffee -m -c lib/

www-data@naturalatlas:/var/www/naturalatlas.com/current/node_modules/neo4j$

Still no dice.

TypeError: undefined is not a function
    at /var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:169:5
    at Object.__g.trampoline.flush (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:23:29)
    at Request.___ [as _callback] (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:120:61)
    at Request.self.callback (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:129:22)
    at Request.EventEmitter.emit (events.js:98:17)
    at Request.<anonymous> (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:873:14)
    at Request.EventEmitter.emit (events.js:117:20)
    at IncomingMessage.<anonymous> (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:824:12)
    at IncomingMessage.EventEmitter.emit (events.js:117:20)
    at _stream_readable.js:920:16

aseemk · 2014-10-01T02:16:35Z

Hmm, your shell snippet shows current or shared in the path, before node_modules, but your stack trace doesn't. Just a sanity check: is that expected/right?

brianreavis · 2014-10-01T03:00:15Z

Good catch – there was something funny going on there. I just fixed that up and voilà – it works. Looks like streamline was the one to blame. Thanks for sticking with this, I appreciate it.

ReferenceError: somethingundefined is not defined
    at /var/www/local/naturalatlas.com/server/routes/test.js:11:10 (YAY!)
    at /var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:169:5
    at Object.__g.trampoline.flush (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:23:29)
    at Request.___ [as _callback] (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/streamline/lib/callbacks/runtime.js:120:61)
    at Request.self.callback (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:129:22)
    at Request.EventEmitter.emit (events.js:98:17)
    at Request.<anonymous> (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:873:14)
    at Request.EventEmitter.emit (events.js:117:20)
    at IncomingMessage.<anonymous> (/var/www/local/naturalatlas.com/node_modules/neo4j/node_modules/request/request.js:824:12)
    at IncomingMessage.EventEmitter.emit (events.js:117:20)

Footnote: A bit of a religious question here: why not drop CoffeeScript and streamline? Don't they create unneeded complexity for questionable gains?

aseemk · 2014-10-01T14:42:15Z

Great that recompiling fixed it! I'll re-compile and re-publish soon then.

Re: why CoffeeScript & Streamline: yep, it's subjective, but to my taste (and having written code with and without both), the gains they provide are substantial. It's hard to really convey this without trying it out for yourself, but I prepared a presentation on this for CoffeeScript a while back:

http://aseemk.com/talks/intro-to-coffeescript

I've yet to do something similar for Streamline, but really want to.

aseemk · 2014-10-01T14:42:48Z

Keeping this issue open for myself to re-compile and re-publish.

ScOut3R · 2014-10-07T18:06:44Z

Ah, this topic saved my day! :)

sheymann · 2014-10-17T16:46:33Z

+1 I have the same issue

sheymann · 2014-10-19T09:49:48Z

@aseemk when you plan to provide a hotfix release? This bug makes your module broken on all windows platforms. It's event not possile to dev with it.

Btw, this is the real reason to avoid CoffeeScript: https://donatstudios.com/CoffeeScript-Madness
The argument has even been acknowledged by Reginald Braithwaite, the author of CoffeeScript Ristretto!

aseemk · 2014-10-20T02:17:44Z

Sorry for the delay, things have been busy. I will republish tonight.

sheymann · 2014-10-21T00:14:04Z

Thanks a lot!

aseemk added the question label Oct 1, 2014

sheymann mentioned this issue Oct 17, 2014

coffee -m -c lib/ && _coffee -m -c lib/ #141

Closed

aseemk closed this as completed in afcd83f Oct 20, 2014

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

BUG: Try-catches around callback execution #139

BUG: Try-catches around callback execution #139

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

aseemk commented Oct 1, 2014

ScOut3R commented Oct 7, 2014

sheymann commented Oct 17, 2014

sheymann commented Oct 19, 2014

aseemk commented Oct 20, 2014

sheymann commented Oct 21, 2014

BUG: Try-catches around callback execution #139

BUG: Try-catches around callback execution #139

Comments

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

brianreavis commented Oct 1, 2014

aseemk commented Oct 1, 2014

aseemk commented Oct 1, 2014

ScOut3R commented Oct 7, 2014

sheymann commented Oct 17, 2014

sheymann commented Oct 19, 2014

aseemk commented Oct 20, 2014

sheymann commented Oct 21, 2014