NodeJS bug with promise.catch and console.log?

Question

When running the following code, I get different results depending on if I have console.log("fnError: ", fnError) commented out or not. This seems very off to me.

How in the world is a call to console.log affecting my promises?

function run() {
    var fn = function(){
        throw new Error("incorrect message");
    };

    // returns a promise that should fail with
    // an error object whose .message is "correct message"
    var promisifiedFn = function(){
        return Promise.resolve()
            .then(fn)
            .catch((fnError) => {
                // commenting this out fixes things! //
                console.log("fnError: ", fnError);
                ///////////////////////////////////////

                fnError.message = "correct message";
                throw fnError;
            })
    }

    promisifiedFn().catch((e) => {
        console.log("caught error.message:", e.message);
        console.log("caught error:", e);
    });
}
run();

The above produces:

// fnError:  Error: incorrect message
//     at fn (/Users/sam/dev/ethereum/pennyeth/js/temp.js:18:9)
//     at <anonymous>
//     at process._tickCallback (internal/process/next_tick.js:169:7)
//     ...
// caught error.message: correct message
// caught error: Error: incorrect message
//     at fn (/Users/sam/dev/ethereum/pennyeth/js/temp.js:18:9)
//     at <anonymous>
//     at process._tickCallback (internal/process/next_tick.js:169:7)
//     ...

Notice "incorrect message" being logged. And if you comment out console.log("fnError: ", fnError) you get this:

// caught error.message: correct message
// caught error: Error: correct message
//     at fn (/Users/sam/dev/ethereum/pennyeth/js/temp.js:18:9)
//     at <anonymous>
//     at process._tickCallback (internal/process/next_tick.js:169:7)
//     ....

Running node 8.0.0

Answer 1

This is expected behaviour.

Logging the error (which goes through util.inspect or String at least) does evaluate its .stack property. The stack string is not initialised when the error object is instantiated, but is built lazily to save memory. The stack trace will include the error's message, and when you change the .message property it will be reflected or not in the stack trace depending on whether that already had been created.

From the V8 stack trace API description:

For efficiency stack traces are not formatted when they are captured but on demand, the first time the stack property is accessed.

and from the official node Error documentation:

The string representing the stack trace is lazily generated when the error.stack property is accessed.

Answer 2

I was able to reproduce this "bug" with only 4 lines below.

var e = new Error('first');
console.log(e);
e.message = 'new';
console.log(e);

I tried it Chrome 59 and it does not have the same problem.

However Node 7.9.0, Node 8.0.0, and Node 8.1.2 all have this problem.

I reported as a bug on GitHub #13832 so we will see what comes of it.

Update 1: To show this is not a timing issue, we can add setTimeout calls

var e = new Error('first');
console.log(e);
setTimeout(() => { e.message = 'new'; }, 1000);
setTimeout(() => console.log(e), 2000);

The problem persists even if we wait to call console.log() which makes me believe the output is cached.

Update 2: I got a response from the mscdex on GitHub:

This is expected because what you're seeing is the stack trace, which includes the error message once it's generated. The stack trace is generated lazily and only once (for performance reasons), so that is why you see the same output both times.

If you however change your code to output e.message, you will see the expected change in output.

Ultimately, both mscdex and Bergi are saying the root cause is lazy evaluation.

What you're doing is probably not a common scenario so I would avoid doing it in the future since it doesn't appear the node.js team will change this behavior.