How to console.log an error with stack trace in node.js?

Question

I've been trying to debug my node app to find the source of an error in my log that shows up only as "Error: Can't set headers after they are sent", with no trace information or any context.

As it happens, I think I've now fixed this... I am using connect-timeout and I was continuing processing a callback passed to an asynchronous network operation, which callback would eventually try to do a res.send(), despite req.timedout having been set to 'true' by connect-timeout during the network operation.

BUT I still can't understand why my log wasn't showing trace information for this error. Anywhere that an error is returned in my code I log it to the console with:

console.log(err);

If there is trace information available in the err object, and this seems to be placed in err.stack, shouldn't the above statement dump the whole content of err (including err.stack) to the console log? My understanding is that I wouldn't be losing any information by doing the above, compared e.g. to:

console.log(err.stack);

But posts like this one seem to suggest otherwise (though the linked post has now been updated).

I actually go further, and add some relevant text to help locate the error:

console.log('error in dodgyFunction:', err);

But despite this, I was still only getting "Error: Can't set headers after they are sent", without any of the context I'd put it. Would this be because this console error message is output within an external library (like express)? I thought that external libraries should send errors back to the main code to be dealt with accordingly?

Edit: here's an example of where I put my error and timeout checking, at the top of the callback function passed to the async operation:

var execFile = require('child_process').execFile;
execFile('dodgycommand', options, function(error, stdout, stderr) {
    if (req.timedout) {
        console.log('timeout detected whilst running dodgycommand, so aborting...');
        return;
    }
    if (error) {
        console.log('error running dodgycommand:', error);
        res.sendStatus(400);
        return;
    }

    // ... it's safe to continue ...

}

I basically follow this same pattern throughout.

Answer 1

I've just worked out what was going on, and I hope this will help others to avoid this beginner's error.

For some of my error logging I was using something like the following, using string concatenation to construct the error message:

console.log('error in function abc: ' + err + ' whilst doing xyz');

whereas elsewhere I was using something like the following, just passing the pieces of the error message as separate arguments to console.log:

console.log('error in function xyz:', err, 'whilst doing abc');

I now see that these give different results!

The former must stringify err so that it can be concatenated with the other parts of the message, and according to this, in doing so it just uses the message part.

However, in the latter form the err object must be processed by console.log unadulterated, and dumped as a whole.

This explains why I was sometimes not seeing the whole content of the error, as I was expecting, and other times I was.

As for console log messages put there by other libraries, something else to check is that you're not filtering out the 'stack' parts of the log messages in your log viewer... turns out that I was (in order to save on log quota... am using papertrail)... d'oh. I was doing so by filtering out any lines starting with ____at (four spaces followed by 'at'), for example ____at Request.self.callback.

Answer 2

I've installed n now and I can confirm the following:

Node 4.0.0

Using console.log(err) prints only the error message.

Node 7.7.0 (latest)

Using console.log(err) prints the error message and the full stack.

I've confirmed that this behavior changed on version 6.0.0. So, if you use an older version, I suggest that you update your Node.js or use console.log(err.stack) instead to print the full stack.

Answer 3

Your pattern looks generally common, though I'll say that as a rule I don't like it, more on that in a second.

As for your main question, it's really hard to answer it based on what you've provided. If you show the actual code rather than the "I generally follow this pattern", it might help. But it's equally possible that the error was being thrown somewhere that you weren't expecting, and so your console.log wasn't getting called at all.

Seems like you're looking for best practices, so I'll give you what I think is the best I have found so far.

First, don't use console.log for logging. It's not horrible, but you can do much, much better. My favorite is to use morgan as middleware for logging request information, and debug for application logging.

With debug you can set up custom log levels and listen to whatever level you want with whatever level of granularity you want. It's all controlled by setting the DEBUG environment variable, and in production you can redirect to file or whatever other destination you want. Further, many node modules (including Express and Connect) use Debug as their logger under the hood, so by tweaking your DEBUG variable you can see as much or little of their inner logging as you want. very useful for figuring out what went wrong where.

Second, as I said I don't use the pattern you have at all when it comes to routing. I've found it's easy to accidentally send headers more than once if I am not careful, so my middleware always return next() and responses are only sent in actual handlers that I can be sure fire only once. When it comes to error, I always pass next(e) which I can then handle in an error handler function. I also created the praeter library to provide standard errors based on web status codes and a generic error handler.

The pattern looks something like this:

// middleware function to put something on the request object
app.use((req, res, next) => {
  MyModel.doSomething((e, thing) => {
    if (e) return next(e);
    if (!thing) return next(new NotFound()); // NotFound is an error in praeter that equates to a 404. 
    req.thing = thing;
    return next();
  });
});

Then later

// log in here is a reference to my debug configured log object
app.use((err, req, res, next) => {
  log.error(err);
  log.error(err.stack);
  return res.status(err.statusCode || 500).send(err.message)
});

Note this is a simple example of a final error handler. I often have several of these where I might handle different error codes differently, depending on application needs.