AndreasMadsen / trace

Creates super long stack traces
https://trace.js.org
MIT License
194 stars 18 forks source link

Stack Trace makes no sense #36

Closed ben-page closed 5 years ago

ben-page commented 6 years ago

I using Node v9.3.0 and the stack traces provided by this module make no sense to me. Here's the example that I'm using:

'use strict';
require('trace');
require('clarify');
Error.stackTraceLimit = 100;

function thing() {
    return new Promise((resolve, reject) => {
        setTimeout(() => {
            reject(new Error('error'));
        }, 10);
    });
}

async function test() {
    try {
        await thing();
    } catch(err) {
        console.error(err);
    }
}

test();

Here's the call stack that I receive:

Error: error
    at Timeout.setTimeout [as _onTimeout] (C:\projects\test\test.js:9:20)
    at test (C:\projects\test\test.js:16:15)
    at Object.<anonymous> (C:\projects\test\test.js:22:1)
    at test (C:\projects\test\test.js:16:15)
    at Object.<anonymous> (C:\projects\test\test.js:22:1)
    at test (C:\projects\test\test.js:14:20)
    at Object.<anonymous> (C:\projects\test\test.js:22:1)

The first three frames make sense, but the rest is nonsense as far as I can tell.

ben-page commented 6 years ago

It may be obvious, but clarify is not causing the problem. Here's the stack trace without clarify.

Error: error
    at Timeout.setTimeout [as _onTimeout] (C:\projects\test\test.js:9:20)
    at ontimeout (timers.js:466:11)
    at tryOnTimeout (timers.js:304:5)
    at Timer.listOnTimeout (timers.js:264:5)
    at test.<anonymous> (<anonymous>)
    at test (C:\projects\test\test.js:16:15)
    at Object.<anonymous> (C:\projects\test\test.js:22:1)
    at Module._compile (module.js:660:30)
    at Object.Module._extensions..js (module.js:671:10)
    at Module.load (module.js:573:32)
    at tryModuleLoad (module.js:513:12)
    at Function.Module._load (module.js:505:3)
    at Function.Module.runMain (module.js:701:10)
    at startup (bootstrap_node.js:194:16)
    at bootstrap_node.js:618:3
    at test.<anonymous> (<anonymous>)
    at test (C:\projects\test\test.js:16:15)
    at Object.<anonymous> (C:\projects\test\test.js:22:1)
    at Module._compile (module.js:660:30)
    at Object.Module._extensions..js (module.js:671:10)
    at Module.load (module.js:573:32)
    at tryModuleLoad (module.js:513:12)
    at Function.Module._load (module.js:505:3)
    at Function.Module.runMain (module.js:701:10)
    at startup (bootstrap_node.js:194:16)
    at bootstrap_node.js:618:3
    at <anonymous>
    at test (C:\projects\test\test.js:14:20)
    at Object.<anonymous> (C:\projects\test\test.js:22:1)
    at Module._compile (module.js:660:30)
    at Object.Module._extensions..js (module.js:671:10)
    at Module.load (module.js:573:32)
    at tryModuleLoad (module.js:513:12)
    at Function.Module._load (module.js:505:3)
    at Function.Module.runMain (module.js:701:10)
    at startup (bootstrap_node.js:194:16)
    at bootstrap_node.js:618:3
cspotcode commented 5 years ago

I think it only makes sense when you look at these lines in isolation:

    at Timeout.setTimeout [as _onTimeout] (C:\projects\test\test.js:9:20)
    // reject(new Error('error'));

    at test (C:\projects\test\test.js:16:15)
    // await thing();

    at Object.<anonymous> (C:\projects\test\test.js:22:1)
    // test();

The stack trace is a bit more readable when it's formatted like Bluebird's long stack traces. But still confusing, and seems like something's not right:

Error: error
    at Timeout.setTimeout [as _onTimeout] (C:\projects\test\test.js:9:20)
    at test (C:\projects\test\test.js:16:15)
    at Object.<anonymous> (C:\projects\test\test.js:22:1)
From previous event:
    at test (C:\projects\test\test.js:16:15)
    at Object.<anonymous> (C:\projects\test\test.js:22:1)
From previous event:
    at test (C:\projects\test\test.js:14:20)
    at Object.<anonymous> (C:\projects\test\test.js:22:1)
AndreasMadsen commented 5 years ago

Looks like this is related to when error.stack is evaluated. That is a V8 issue.