Node.js stack trace info

Question

I'm looking for info on Node.js error stacks, and why layers seems to be missing from them. We are throwing an error when a user is not found in our Mongo database. We are using Mongoose as an ODM. Our error management is pretty simple - when the call to Mongoose comes back empty, we create a new error object. We are using Winston to log, and it logs our error, with the stack trace. But we seem to be missing some information. You'll notice the line of our code below, where the error occurs - "/var/app/current/models/users_model.js:19:9". Problem is, it's buried in a bunch of Mongoose calls, and does not show which of our modules actually called it. I don't know whether this is normal, or is just that because it's stuck in a Mongoose promise chain, and the information I need has been chopped off. Any thoughts or info would be much appreciated.

"message" : "{\"message\":\"USER_NOT_FOUND\",\"stack\":\"Error: USER_NOT_FOUND\n at _e (/var/app/current/global/response.js:69:11)\n at Promise. (/var/app/current/models/users_model.js:19:9)\n at Promise. (/var/app/current/node_modules/mongoose/node_modules/mpromise/lib/promise.js:162:8)\n at Promise.EventEmitter.emit (events.js:95:17)\n at Promise.emit (/var/app/current/node_modules/mongoose/node_modules/mpromise/lib/promise.js:79:38)\n at Promise.fulfill (/var/app/current/node_modules/mongoose/node_modules/mpromise/lib/promise.js:92:20)\n at /var/app/current/node_modules/mongoose/lib/query.js:1784:30\n at /var/app/current/node_modules/mongoose/lib/utils.js:414:16\n at /var/app/current/node_modules/mongoose/node_modules/mongodb/lib/mongodb/collection.js:953:5\n at /var/app/current/node_modules/mongoose/node_modules/mongodb/lib/mongodb/cursor.js:683:35\"}"

Answer 1

I found a couple of things finally, that worked in combo. One was an npm module called "longjohn". This gathers stack traces from multiple async calls. I added it to the top of my server.js file:

    require('longjohn').async_trace_limit = 500;

But the length of the individual stack traces is still too short. So I started node with:

    node --stack-trace-limit=500 server.js

This then gave me a monster stack trace, but it did contain the information I wanted. Definitely not something to be added in production, but certainly great for debugging in dev.

Be really nice if there was a way to gather some variables and toss them in as well. Our real problem we are trying to understand is why a response is coming back empty, which implies invalid data is being passed to it. But can't see that in the stack trace.

Answer 2

This is normal. Database calls in Node.js are (usually) asynchronous, so the top of your stack trace is going to be the event representing data coming back from the database. The stack that caused that request to be made is done at that point, so the information you're looking for is gone.