Node: Improve stack traces for exceptions thrown at a top-level

[fresheneesz]

• Version: 5.1.0
• Platform: Centos 6.x
• Subsystem: require

When exceptions are thrown at a top level, there's a distinct lack of information as far as how that module was required. If you have a dependency chain where a requires b which requires c, if c throws an exception while building its module, node doesn't tell you about b or a, which can make it difficult to debug things when there are interactions between modules or global variables.

For example, I'm seeing this exception:

Error: Logger not yet initialized! Initialize first!
    at Error (native)
    at init (/home/vagrant/backend/git/node_modules/logger.js:116:19)
    at eval (eval at proto (/home/vagrant/backend/node_modules/proto/proto.js:57:34), <anonymous>:3:39)
    at Object.<anonymous> (/home/vagrant/backend/git/node_modules/security.js:7:31)
    at Module._compile (module.js:425:26)
    at Object.Module._extensions..js (module.js:432:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:313:12)
    at Module.require (module.js:366:17)
    at require (module.js:385:17)

This doesn't tell me what file required security.js, which would be incredibly helpful to me right now in debugging this problem with my code. Also, the part of the stack trace containing internal node stuff is very unlikely to be useful to a developer unless what they're developing is node itself. I want to suggest that a stacktrace like the following be generated instead:

Error: Logger not yet initialized! Initialize first!
    at Error (native)
    at init (/home/vagrant/backend/git/node_modules/logger.js:116:19)
    at eval (eval at proto (/home/vagrant/backend/node_modules/proto/proto.js:57:34), <anonymous>:3:39)
    at Object.<anonymous> (/home/vagrant/backend/git/node_modules/security.js:7:31)
    required by (db.js:4:16)
    required by (utils.js:9:26)
    required by (server.js:21:20)
    required by (appServer.js:3:36)

[gireeshpunathil]

Agree on the scope for improvement in the exception stack. But is it really the whole of your stack trace? Isn't there further frame(s) beneath the 'require' one, the caller script which needed the security module?

[fresheneesz]

@gireeshpunathil That's all it prints out. I have noticed that in other stack traces I do get the module that required the current one, but only that one (none of the modules that required that parent module up the chain).

[bnoordhuis]

The depth of the stack trace is controlled by the --stack_trace_limit flag. It defaults to 10, that's why it ends at require (module.js:385:17) in your example.

Also, the part of the stack trace containing internal node stuff is very unlikely to be useful to a developer unless what they're developing is node itself.

That may change in the future, although many people do seem to find it useful.

[fresheneesz]

@bnoordhuis

--stack_trace_limit

Oh really? I had no idea. That's really good to know, thanks!

many people do seem to find it useful.

Who? What do they find it useful for?

[addaleax]

Would it be a good idea to increase the Error.stackTraceLimit just for the first tick/for Module.runMain? I can definitely see why it can be frustrating to see those cut-off stack traces when something is require()d.

[bnoordhuis]

I don't have a strong opinion on that but something to keep in mind is that longer stack traces are more expensive to collect. It's going to slow down start-up code that throws (and catches) a lot of exceptions.

[fresheneesz]

@addaleax I think that's a great idea.

@bnoordhuis The expense of collecting a stack trace isn't important when you have an error that crashes your program. Even when you catch an exception and continue, errors should be rare and thus the expense relatively negligible regardless of the expense of an individual error.

[addaleax]

Yeah, I’m aware that stack traces come at a cost, but the usefulness/cost ratio of longer stack traces on module loading is probably quite different from the one for normal operation. What may be tricky is resetting the value after Module.runMain, I’m not sure there’s an easy/reliable way to tell whether the value has been changed from userland.

[bnoordhuis]

Even when you catch an exception and continue, errors should be rare and thus the expense relatively negligible regardless of the expense of an individual error.

There are several frameworks that generate thousands, even tens of thousands, exceptions at start-up. So no, I wouldn't say that the cost of exceptions is irrelevant.

[fresheneesz]

@bnoordhuis What frameworks do that? Isn't it their fault if they choose to program in a way that's against best practice in every language that has exceptions?

Also, I'm still curious as to who you claim finds node.js internals inside their stack traces useful other than people developing node.js itself.

[Qard]

Perhaps we could just document the --stack_trace_limit flag somewhere, so users are more aware that the stack length limit is adjustable? @nodejs/documentation

[eljefedelrodeodeljefe]

@fresheneesz ...I do find it useful, because it gives you the full picture. It should be worth for you too, since you argue for more information. Also this is incredibly useful for bug reporting, since implementors, node-core people and package authors are receiving bug reports where internal code is probably more useful than application code.

@Qard Problem is that it's a v8 flag that we excluded from cli documentation. It would maybe then need to go in here can someone mark this help_wanted?

[addaleax]

@eljefedelrodeodeljefe Added the label as requested, and +1 to your suggestion of adding that to the Error docs.

[bnoordhuis]

What frameworks do that? Isn't it their fault if they choose to program in a way that's against best practice in every language that has exceptions?

Node.js itself until not too long ago, for example; see #1801. :-)

[fresheneesz]

@eljefedelrodeodeljefe

receiving bug reports where internal code is probably more useful than application code

That's a reasonable point. Tho repro steps are just as good if node.js devs have a switch they can turn on to see node internals, right?

@bnoordhuis

Node.js itself until not too long ago

Ah, the best practice of not using fs.exists and instead using the error from readFile etc to determine file existence. To be fair, you also said node.js no longer does this, and anyone else that has massive use of the need for file existence checks can use the same technique node.js itself is using to limit the number of exceptions created. I approve of the decision to optimize node.js by limiting use of exceptions in non-exceptional cases, and that's in agreement with my assertion that the expense of exceptions shouldn't usually be a consideration in design. In other words, I think your example supports my point of view and not yours.

[eljefedelrodeodeljefe]

@fresheneesz though I see your point, altering this, apart from on/off logic, belongs rather to frontends like you have in some editors. xcode for example blends out non resolved stack trace addresses and I believe you can blend out e.g. v8 strack traces in some applications. But as I said, this then belongs to applications.

[fresheneesz]

@eljefedelrodeodeljefe It seems a bit backwards to me that v8 stack trace lines "belong to applications". This strikes mes as similar to something like stacktrace.js which used to output stacktrace.js specific trace lines when you use it to analyze your exceptions. It should be stacktrace.js that makes sure to remove any lines it puts into your stack traces. Its a similar situation for node, so I respectfully disagree that removing stacktrace lines belongs in userspace.

[lance]

Since Error.stackTraceLimit is documented and documenting the --stack-trace-limit flag was deemed distasteful, I am going to go ahead and close this as there doesn't seem to be anything else to be done about it.

Feel free to reopen if any of you feel otherwise.