Wrong stack?
Closed this issue · 3 comments
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.
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:
- 2 lines in each tick there only exists because I hook intro some node monitor API
- all node internal lines because you use clarify.
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.
It's all async. co
ensures that everything is async.
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).