AndreasMadsen / trace

Creates super long stack traces
https://trace.js.org
MIT License
194 stars 18 forks source link

Wrong stack? #11

Closed iliakan closed 10 years ago

iliakan commented 10 years ago

I'm developing and didn't have the time to leave it hanging yet, but got another thing.

Please consider the video here: http://ilyakantor.ru/screen/2014-09-13_1705.swf

In short, I refresh the page and the stack trace changes. But the control flow is the same. Is it normal?

I'd like to point out: it skips kind of a lot of intermediate middlewares in the stack. Is it intentionally?

Here's the last trace:

    Cannot read property 'token' of undefined
        at res (/js/javascript-nodejs/node_modules/jade/lib/jade.js:175:38)
        at Object.exports.render (/js/javascript-nodejs/node_modules/jade/lib/jade.js:300:10)
        at Object.exports.renderFile (/js/javascript-nodejs/node_modules/jade/lib/jade.js:336:18)
        at Object.render (/js/javascript-nodejs/modules/setup/render.js:131:19)
        at Object.get (/js/javascript-nodejs/hmvc/tutorial/controller/article.js:65:20)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:74:21)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:67:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at exit (/js/javascript-nodejs/node_modules/co/index.js:51:7)
        at Object.next (/js/javascript-nodejs/node_modules/co/index.js:76:18)
        at Object.<anonymous> (/js/javascript-nodejs/node_modules/co/index.js:93:18)
        at Immediate._onImmediate (/js/javascript-nodejs/node_modules/co/index.js:52:14)
        at Connection.start (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection.js:173:29)
        at _connect (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:205:16)
        at /js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:136:15
        at null.<anonymous> (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:133:11)
        at Socket.<anonymous> (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection.js:318:10)
        at Connection.start (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection.js:173:29)
        at _connect (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:205:16)
        at /js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:136:15
        at null.<anonymous> (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:133:11)
        at Socket.<anonymous> (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection.js:318:10)
        at Connection.start (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection.js:173:29)
        at _connect (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:205:16)
        at ConnectionPool.start (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:225:3)
        at Server.connect (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/connection/server.js:698:18)
        at Db.open (/js/javascript-nodejs/node_modules/mongoose/node_modules/mongodb/lib/mongodb/db.js:278:23)
        at NativeConnection.doOpen (/js/javascript-nodejs/node_modules/mongoose/lib/drivers/node-mongodb-native/connection.js:56:11)
        at NativeConnection.Connection._open (/js/javascript-nodejs/node_modules/mongoose/lib/connection.js:410:15)
        at NativeConnection.Connection.open (/js/javascript-nodejs/node_modules/mongoose/lib/connection.js:251:8)
        at Mongoose.connect (/js/javascript-nodejs/node_modules/mongoose/lib/index.js:212:15)
        at Object.<anonymous> (/js/javascript-nodejs/modules/config/mongoose.js:21:10)
        at Object.<anonymous> (/js/javascript-nodejs/modules/app.js:13:18)
        at Object.<anonymous> (/js/javascript-nodejs/bin/server:5:13)

P.S. That had both trace and clarify on and stack limit of 1000.

AndreasMadsen commented 10 years ago

Without knowing anything about co or mongoose I would say that they do some sort of quick pooling. It is particular apparent with co there runs a recursive setImmediate loop, until some condition is meet. Sometimes this condition is meet immediately in other cases it takes a few ticks. I think the same is the case with mongoose. It seams to manage some connection pool, the size of this pool will obviouse vary. Sometimes there is an available socket and sometimes a socket needs to be opened.

tl;dr You flow may be the same, but the modules you use can have state dependent conditions, in each case different async or sync routes may be seen.

I'd like to point out: it skips kind of a lot of intermediate middlewares in the stack. Is it intentionally?

It shouldn't skip anything, except for:

My guess is that some of this middleware is sync or lazy async, thus co executes it as A(); B(); C(); and you won't see any stack lines from those modules.

iliakan commented 10 years ago

It's all async. co ensures that everything is async.

AndreasMadsen commented 10 years ago

Would you expect the middleware stack lines to be after the very last stack line you see. In that case it may be because you have stack limit of 1000 and clarify enabled simultaneously.

The reason is that in the better-memory branch, trace cuts the stack lines so there is only 1000, but the node internal lines are included in this count. It is first when the actual .stack string is produced that the node internal lines are filtered. Thus you can easily end up with a .stack with less than 1000 lines. This is known bug (why I haven't published better-memory), and there a fix for it. I just haven't implemented it (I'm waiting for confirmation that better-memory is better).