nodejs / help

:sparkles: Need help with Node.js? File an Issue here. :rocket:
1.46k stars 279 forks source link

Replicate the Chrome DevTools Call Stack window using Inspect/Debugger #2977

Closed markwylde closed 4 years ago

markwylde commented 4 years ago

One of the best features of NodeJS (and any language I've ever used), in my opinion, is the ability to get all the complete call stacks of the running app.

Let's say I have a very small example app:

function asyncThing (connection, sql, parameters, callback) {
  return fs.readFile('index.js', 'utf8').then(a => {
    throw new Error('who knows what went wrong?');
  });
}

async function main () {
  setTimeout(() => {
    asyncThing();
  }, 250);
}

main();

When I use ndb, the chrome devtools, vscode, etc, I get this amazing window:

Screen Shot 2020-09-12 at 12 35 35 pm

Of course, it tells me the line that actually threw. But this is almost always inside a library or something that isn't the problem. The problem is where I am calling it from (in another call stack).

That screenshot (the Call Stack window) show's me all the call stacks still "alive?" and is extremely useful.

I want to get this into the terminal when I'm debugging my code. I've tried --async-stack-traces, the trace library and other similar tools. I've even tried writing my own library that uses async_hooks, but none of them work 100% of the time, or as good as that window in the debugging tools.

What I really want, is to be able to recreate that call stack box (yes, I know there are blackboxed items being hidden and it might be messy). That's all good. But I can't seem to recreate it.

What I've tried so far?

I am running my app with the following code:

const fs = require('fs')
const inspector = require('inspector');
inspector.open(9229, '127.0.0.1', false);
fs.writeFileSync('/tmp/hazstax.uri', inspector.url());
inspector.waitForDebugger();

Then running another app that does:

const WebSocket = require('ws');
const ws = new WebSocket(fs.readFileSync('/tmp/hazstax.uri', 'utf8'));

ws.on('open', async function () {
  await send({ method: 'Runtime.runIfWaitingForDebugger' });
  await send({ method: 'Debugger.enable' });
  await send({ method: 'Runtime.setAsyncCallStackDepth', params: { maxDepth: 100000000 } });
  await send({ method: 'Debugger.setPauseOnExceptions', params: { state: 'all' } });
});

It's really cool and I get some great information. I won't paste here as it's quite long, but I've attached. debug-logs.txt

So why am I still complaining?

Again, like all async debugging tools, it still refuses to give me: a) all the alive call stacks b) the actual line number of the executing function that started the failure tree

The line number that called: asyncThing(); should be "index.js:7" but it appears no where in that debug log. As in, the web socket connection never sends me a single bit of text with that line number in it.

The documentation for Chrome DevTools (https://chromedevtools.github.io/devtools-protocol/tot/Debugger/#method-setAsyncCallStackDepth) is amazing, and has been so useful in getting me as far as I have. But I can't find anything in there to give me the full stack trace information.

I got excited when I saw the Debugger.getStackTrace but then it required an ID which seems impossible to retrieve.

I know this is long and probably not interesting to anyone, but it would mean the world to me if someone, anyone, could just point me in the right direction.

Summary TL;DR;

To try and be concise. I want to have this:

Screen Shot 2020-09-12 at 12 53 53 pm

In my terminal like:

ptest % node index.js 
(node:86740) UnhandledPromiseRejectionWarning: Error: who knows what went wrong?
    at /Users/mark/Documents/Projects/ptest/asyncThing.js:5:11
    Promise.then (async)
    asyncThing at /Users/mark/Documents/Projects/ptest/asyncThing.js:4
    anonymous index.js:7
    Timeout (async)
    setTimeout at timers.js:157
    main at index.js:6
    (anonymous) at index.js:11

I don't mind having loads of other lines in there from internal modules. I can filter them out, blacklist them, etc.

Thanks to anyone who takes the time to read this and help me out.

markwylde commented 4 years ago

I might be making some progress. I've just discovered the "Protocol monitor" which lets you "spy" on what the DevTools are actually doing.

There's a lot to parse, but it appears that the DevTools gets a "parent" object in the asyncStackTrace. I feel that's what's populating the call stack window.

Screen Shot 2020-09-12 at 1 46 25 pm
markwylde commented 4 years ago

Okay it looks like lineNumber starts at "0" not "1", meaning the async stack traces where actually logging the position of the calling function. This is good, but it's still not providing all the stacks.

Why do the Chrome DevTools get a "parent" field but I don't?

Screen Shot 2020-09-12 at 4 00 00 pm

The current commands I'm trying are:

await send({ method: 'Runtime.runIfWaitingForDebugger' });
await send({ method: 'Debugger.enable', params: { maxScriptsCacheSize: 100000000 } });
await send({ method: 'Profiler.enable' });
await send({ method: 'Runtime.enable' });
await send({ method: 'Runtime.setAsyncCallStackDepth', params: { maxDepth: 32 } });
await send({ method: 'Debugger.setBlackboxPatterns', params: { patterns: ['^internal[\/].*|bin/npm-cli.js$|bin/yarn.js$'] } });
await send({ method: 'Debugger.setPauseOnExceptions', params: { state: 'uncaught' } });
markwylde commented 4 years ago

Success! The order of executing mattered. This finally worked.

await send({ method: 'Profiler.enable' });
await send({ method: 'HeapProfiler.enable' });
await send({ method: 'NodeWorker.enable' });
await send({ method: 'Runtime.enable' });
await send({ method: 'Runtime.setAsyncCallStackDepth', params: { maxDepth: 128 } });
await send({ method: 'Runtime.runIfWaitingForDebugger' });
await send({ method: 'Debugger.enable', params: { maxScriptsCacheSize: 100000000 } });
await send({ method: 'Debugger.setBlackboxPatterns', params: { patterns: ['^internal[\/].*|bin/npm-cli.js$|bin/yarn.js$'] } });
await send({ method: 'Debugger.setPauseOnExceptions', params: { state: 'uncaught' } });

Closing this as I no longer need help. Hope this helps someone.

For anyone interested, the outcome of all this was the project below:

http://github.com/markwylde/hazlines

LRagji commented 1 year ago

Not sure why you said no one would be intrested in this, cause i am building something similar only issue is i am within the application itself and trying stdout for reporting these messages under feature flag, this post helps