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.