CODEWITHSUNDEEP
node.jsasynchronouserror-handling
Andi Giga
Andi Giga

Reputation: 4162

NodeJS 7: How to Show the Correct Stack Trace in Async Mongoose Promises

When I have an error in mongoose promises with bluebird. I don't have the correct line number, which makes it hard for me to find the error. 

unknownFunction("A")#show me the correct line number in the trace
async.timesSeries 100,
  (index, next) ->
     unknownFunction("B") #show me only the line number where I catch the error

process.on 'uncaughtException', (err)->
  console.log err.stack
  console.trace err 
  throw err

Question: How can I get the correct line number instead of the line number where the error is catched?

PS: I found and tried this so far: https://github.com/groundwater/node-stackup But it gives me a lot of unrelated line numbers.

EDIT:

This is how I init mongoose with bluebird:

Promise = require("bluebird")
Promise.config({
  longStackTraces: true
  warnings: {
    wForgottenReturn: false
  }
})
mongoose = require('mongoose')
mongoose.Promise = Promise
mongoose.set('error', true)

Example correct:

enter image description here

  ReferenceError: unknownFunction is not defined

  - patient.update.js:267

Example incorrect:

enter image description here

somepath/.tmp/serve/server.js:294
      throw err;
      ^

ReferenceError: unknownFunction2 is not defined

The error is in patient.update.js line nr 268

Longjohn

With longjohn

somepath/node_modules/longjohn/dist/longjohn.js:192
        throw e;
        ^

ReferenceError: unknownFunction2 is not defined

Stack up

This is what I mean with node-stack-up unrelated lines (same test with unknownFunction2):

    /somepath/myApp/.tmp/serve/server.js:296
      throw err;
      ^

ReferenceError: unknownFunction2 is not defined

    ---- async ----

  - glue.js:150 asyncWrap
    [myApp]/[async-listener]/glue.js:150:28

  - glue.js:401 wrapCallback
    [myApp]/[async-listener]/glue.js:401:35

  - index.js:16 process.nextTick
    [myApp]/[async-listener]/index.js:16:26

  - index.js:126 Kareem.execPost
    [myApp]/[kareem]/index.js:126:20

  - index.js:251 
    [myApp]/[kareem]/index.js:251:15

  - query.js:1616 
    [myApp]/[mongoose]/lib/query.js:1616:5

  - document.js:317 model.Document.init
    [myApp]/[mongoose]/lib/document.js:317:5

  - query.js:1609 completeOne
    [myApp]/[mongoose]/lib/query.js:1609:10

  - query.js:1271 Immediate.<anonymous>
    [myApp]/[mongoose]/lib/query.js:1271:13

  - utils.js:137 Immediate.<anonymous>
    [myApp]/[mquery]/lib/utils.js:137:16

  - timers.js:649 runCallback
    timers.js:649:20

  - timers.js:622 tryOnImmediate
    timers.js:622:5

  - timers.js:594 processImmediate [as _immediateCallback]
    timers.js:594:5


    ---- async ----

  - glue.js:150 asyncWrap
    [myApp]/[async-listener]/glue.js:150:28

  - glue.js:401 wrapCallback
    [myApp]/[async-listener]/glue.js:401:35

  - index.js:16 process.nextTick
    [myApp]/[async-listener]/index.js:16:26

  - pool.js:454 handleOperationCallback
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:454:24

  - pool.js:490 
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:490:9

  - pool.js:429 authenticateStragglers
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:429:16

  - pool.js:463 Connection.messageHandler
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:463:5

  - connection.js:309 Socket.<anonymous>
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/connection.js:309:
    22

  - events.js:96 emitOne
    events.js:96:13

  - events.js:188 Socket.emit
    events.js:188:7

  - _stream_readable.js:176 readableAddChunk
    _stream_readable.js:176:18

  - _stream_readable.js:134 Socket.Readable.push
    _stream_readable.js:134:10

  - net.js:551 TCP.onread
    net.js:551:20

  - glue.js:188 TCP.onread
    [myApp]/[async-listener]/glue.js:188:31


    ---- async ----

  - glue.js:150 asyncWrap
    [myApp]/[async-listener]/glue.js:150:28

  - glue.js:401 wrapCallback
    [myApp]/[async-listener]/glue.js:401:35

  - index.js:88 Socket.connect
    [myApp]/[async-listener]/index.js:88:29

  - net.js:74 Object.exports.connect.exports.createConnection
    net.js:74:35

  - connection.js:389 Connection.connect
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/connection.js:389:
    11

  - pool.js:1059 _createConnection
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:1059:14

  - pool.js:1151 
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:1151:13

  - pool.js:1082 waitForAuth
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:1082:39

  - pool.js:1090 
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:1090:5

  - pool.js:957 
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:957:21

  - glue.js:188 
    [myApp]/[async-listener]/glue.js:188:31

  - next_tick.js:67 _combinedTickCallback
    internal/process/next_tick.js:67:7

  - next_tick.js:98 process._tickCallback
    internal/process/next_tick.js:98:9


    ---- async ----

  - glue.js:150 asyncWrap
    [myApp]/[async-listener]/glue.js:150:28

  - glue.js:401 wrapCallback
    [myApp]/[async-listener]/glue.js:401:35

  - index.js:16 process.nextTick
    [myApp]/[async-listener]/index.js:16:26

  - pool.js:956 Pool.write
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:956:13

  - cursor.js:288 CommandCursor.Cursor._find
    [myApp]/[mongoose]/[mongodb-core]/lib/cursor.js:288:22

  - cursor.js:588 nextFunction
    [myApp]/[mongoose]/[mongodb-core]/lib/cursor.js:588:10

  - cursor.js:696 CommandCursor.Cursor.next [as _next]
    [myApp]/[mongoose]/[mongodb-core]/lib/cursor.js:696:3

  - cursor.js:849 fetchDocs
    [myApp]/[mongoose]/[mongodb]/lib/cursor.js:849:10

  - cursor.js:876 toArray
    [myApp]/[mongoose]/[mongodb]/lib/cursor.js:876:3

  - cursor.js:829 CommandCursor.Cursor.toArray
    [myApp]/[mongoose]/[mongodb]/lib/cursor.js:829:44

  - db.js:1662 indexInformation
    [myApp]/[mongoose]/[mongodb]/lib/db.js:1662:39

  - db.js:1626 Db.indexInformation
    [myApp]/[mongoose]/[mongodb]/lib/db.js:1626:44

  - db.js:1129 ensureIndex
    [myApp]/[mongoose]/[mongodb]/lib/db.js:1129:8

  - db.js:1105 Db.ensureIndex
    [myApp]/[mongoose]/[mongodb]/lib/db.js:1105:44

  - collection.js:1891 ensureIndex
    [myApp]/[mongoose]/[mongodb]/lib/collection.js:1891:13

  - collection.js:1879 Collection.ensureIndex
    [myApp]/[mongoose]/[mongodb]/lib/collection.js:1879:44

  - collection.js:126 NativeCollection.(anonymous function) [as ensureIndex]
    [myApp]/[mongoose]/lib/drivers/node-mongodb-native/collection.js:12
    6:28

  - model.js:1019 create
    [myApp]/[mongoose]/lib/model.js:1019:22

  - model.js:1033 Immediate.<anonymous>
    [myApp]/[mongoose]/lib/model.js:1033:7

  - timers.js:649 runCallback
    timers.js:649:20

  - timers.js:622 tryOnImmediate
    timers.js:622:5

  - timers.js:594 processImmediate [as _immediateCallback]
    timers.js:594:5


    ---- async ----

  - glue.js:150 asyncWrap
    [myApp]/[async-listener]/glue.js:150:28

  - glue.js:401 wrapCallback
    [myApp]/[async-listener]/glue.js:401:35

  - index.js:16 process.nextTick
    [myApp]/[async-listener]/index.js:16:26

  - _stream_writable.js:377 onwrite
    _stream_writable.js:377:15

  - _stream_writable.js:90 WritableState.onwrite
    _stream_writable.js:90:5

  - net.js:724 Socket._writeGeneric
    net.js:724:5

  - net.js:734 Socket._write
    net.js:734:8

  - _stream_writable.js:334 doWrite
    _stream_writable.js:334:12

  - _stream_writable.js:320 writeOrBuffer
    _stream_writable.js:320:5

  - _stream_writable.js:247 Socket.Writable.write
    _stream_writable.js:247:11

  - net.js:661 Socket.write
    net.js:661:40

  - connection.js:500 Connection.write
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/connection.js:500:
    53

  - pool.js:1137 
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:1137:26

  - pool.js:1082 waitForAuth
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:1082:39

  - pool.js:1090 
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:1090:5

  - pool.js:957 
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:957:21

  - glue.js:188 
    [myApp]/[async-listener]/glue.js:188:31

  - next_tick.js:67 _combinedTickCallback
    internal/process/next_tick.js:67:7

  - next_tick.js:98 process._tickCallback
    internal/process/next_tick.js:98:9


    ---- async ----

  - glue.js:150 asyncWrap
    [myApp]/[async-listener]/glue.js:150:28

  - glue.js:401 wrapCallback
    [myApp]/[async-listener]/glue.js:401:35

  - index.js:16 process.nextTick
    [myApp]/[async-listener]/index.js:16:26

  - pool.js:956 Pool.write
    [myApp]/[mongoose]/[mongodb-core]/lib/connection/pool.js:956:13

  - cursor.js:288 Cursor._find
    [myApp]/[mongoose]/[mongodb-core]/lib/cursor.js:288:22

  - cursor.js:588 nextFunction
    [myApp]/[mongoose]/[mongodb-core]/lib/cursor.js:588:10

  - cursor.js:696 Cursor.next [as _next]
    [myApp]/[mongoose]/[mongodb-core]/lib/cursor.js:696:3

  - cursor.js:672 nextObject
    [myApp]/[mongoose]/[mongodb]/lib/cursor.js:672:8

  - cursor.js:262 Cursor.next
    [myApp]/[mongoose]/[mongodb]/lib/cursor.js:262:12

  - collection.js:1401 findOne
    [myApp]/[mongoose]/[mongodb]/lib/collection.js:1401:10

  - collection.js:1387 Collection.findOne
    [myApp]/[mongoose]/[mongodb]/lib/collection.js:1387:44

  - collection.js:126 NativeCollection.(anonymous function) [as findOne]
    [myApp]/[mongoose]/lib/drivers/node-mongodb-native/collection.js:12
    6:28

  - node.js:38 NodeCollection.findOne
    [myApp]/[mquery]/lib/collection/node.js:38:19

  - mquery.js:1787 model.Query.Query.findOne
    [myApp]/[mquery]/lib/mquery.js:1787:20

  - query.js:1260 model.Query.Query._findOne
    [myApp]/[mongoose]/lib/query.js:1260:22

  - index.js:239 
    [myApp]/[kareem]/index.js:239:8

  - index.js:18 
    [myApp]/[kareem]/index.js:18:7

  - glue.js:188 
    [myApp]/[async-listener]/glue.js:188:31

  - next_tick.js:67 _combinedTickCallback
    internal/process/next_tick.js:67:7

  - next_tick.js:98 process._tickCallback
    internal/process/next_tick.js:98:9


    ---- async ----

  - glue.js:150 asyncWrap
    [myApp]/[async-listener]/glue.js:150:28

  - glue.js:401 wrapCallback
    [myApp]/[async-listener]/glue.js:401:35

  - index.js:16 process.nextTick
    [myApp]/[async-listener]/index.js:16:26

  - index.js:17 Kareem.execPre

Upvotes: 8

Views: 2076

Answers (4)

Andi Giga
Andi Giga

Reputation: 4162

I was on the wrong hunch (https://github.com/petkaantonov/bluebird/issues/1297).

This issue was not related to nodejs it was a mongoose bug which is closed in a newer version https://github.com/Automattic/mongoose/issues/4209. In older versions it seemed to be required to catch the error at the end of the mongoose query.

Solution:

PatientModel.findOne(newFilterUpdate).exec((err, patient) ->
    ...
).catch (err)->
    console.log "err #{err}"

or upgrading mongoose

Upvotes: 0

SUNDARRAJAN K
SUNDARRAJAN K

Reputation: 2295

For any uncaughtException the server will stop in order to make the server keep on running even when there is an uncaught exception what i have done is created a separate collection for storing error, save error once an uncaught exception occurs and returns.

Collection

var ErrorSchema = new mongoose.Schema({
  err_Message:{type:String},
  err_Stack:{type:String},
  date:{type:Date}
});

Controller

process.on('uncaughtException', function (err) {
    console.log(err);
    console.error((new Date).toUTCString() + ' uncaughtException:', err.message);
    console.error(err.stack);

    var newError = new Error;
    newError.err_Message = err.message;
    newError.err_Stack = err.stack;
    newError.date = moment();
    newError.save(function(saveErr,errData){
        if(!saveErr)
            console.log('New Error is saved');
        else
            console.log('Error in saving error');
    });
    //process.exit(1)
});

The above methods stores the uncaught exception in the Error collection and the process/server does not stops.

Reference: Already answered in Nodejs debug errors in production

Hope this helps.

Upvotes: 0

Pritish Vaidya
Pritish Vaidya

Reputation: 22209

You can try the following tool decofun debug tool to deanomise the anonymous functions.

Complete details mentioned in the following answer written by me in this

thread

The documentation is as mentioned here

Upvotes: 0

idbehold
idbehold

Reputation: 17168

The node-stackup, longjohn, and Bluebird's long stack traces are the best solutions available. I'm not sure what you mean by "it gives me a lot of unrelated line numbers." It's giving you a stack trace, so unless you've written all the code and have zero dependencies then you're bound to see function calls to lines you didn't write regardless of whether the operation is asynchronous or not.

Essentially what these libraries do is just stitch detached stack traces together. Normally JavaScript stack traces won't include anything involving an asynchronous operation, only the most recent synchronous function calls. These libraries monkey patch most methods that can introduce asynchronous behavior (process.nextTick, setTimeout, EventEmitter, etc.). They add code which creates a new stack trace at each of these call sites and stores all of these until an error occurs. It will join all of the stored stack traces together so you can actually walk back through all of the asynchronous operations until you get to the original call site.

Upvotes: 4

Related Questions