Error stacks in log includes null.thing instead of just thing #42417
Comments
|
🤦🏻 I believe this is just something to do with the source map. Disabling shows the correct error stack. Will leave open and let someone else decide if it is still relevant to investigate for source maps, or to leave as is. |
|
@fabiancook are you using native Node sourcemaps? How is that code built? Can you reproduce this with "regular" native node source maps? |
|
These sourcemaps were generated through typescript/
async function Throw1() {
throw new Error();
}
try {
await Throw1();
} catch (error) {
console.log(error);
}
export default 1;
async function Throw1() {
throw new Error();
}
try {
await Throw1();
}
catch (error) {
console.log(error);
}
export default 1;
//# sourceMappingURL=throw1.js.map
What is a native node source map vs what I have here? I see in the documentation
The above has |
|
@bcoe hmm, the |
|
It also omits $ node --version
v17.4.0
$ tsc --module esnext --target esnext --sourcemap ./repro.ts
$ node ./repro.js
Error
at loop (/app/repro.js:8:17)
at async main (/app/repro.js:3:5)
$ node --enable-source-maps ./repro.js
Error
at null.loop (/app/repro.ts:10:17)
at null.main (/app/repro.ts:3:5)
$ node -r @cspotcode/source-map-support/register ./repro.js
Error
at loop (/app/repro.ts:10:17)
at async main (/app/repro.ts:3:5)// repro.ts
async function main() {
await loop();
}
async function loop() {
// Take one lap around the event loop
await void 0;
console.log(new Error().stack?.replaceAll(process.cwd(), '/app')); // redacting / shortening paths
}
main(); |
|
We have a test and bench that checks the performance and correctness of various source-map options: https://github.com/cspotcode/source-map-performance-demo#example-output |
|
If I use node -r source-map-support/register esnext/tests/index.js
Error:
at Throw1 (file:///Users/fabiancook/src/virtualstate/fringe/src/tests/throw.tsx:5:11)
at Object.[Symbol.asyncIterator] (file:///Users/fabiancook/src/virtualstate/fringe/src/component.ts:32:22)
at AsyncGenerator.next (<anonymous>)
at childrenSettledGeneratorInner (file:///Users/fabiancook/src/virtualstate/fringe/src/children.ts:135:24)
at childrenSettledGeneratorInner.next (<anonymous>)
at childrenSettledGeneratorInner (file:///Users/fabiancook/src/virtualstate/fringe/src/children.ts:131:14)
at childrenSettledGeneratorInner.next (<anonymous>)
at childrenSettledGenerator (file:///Users/fabiancook/src/virtualstate/fringe/src/children.ts:112:22)
at childrenSettledGenerator.next (<anonymous>)
at file:///Users/fabiancook/src/virtualstate/fringe/src/children.ts:187:28 |
|
It looks like a simple fix in lib/internal/source_map/prepare_stack_trace.js - if t.getTypeName() returns null we should omit Anyone wants to open a PR? |
|
A fix would probably but not nessarily look like this, this also needs a test: diff --git a/lib/internal/source_map/prepare_stack_trace.js b/lib/internal/source_map/prepare_stack_trace.js
index 0635ee6754..a03718626a 100644
--- a/lib/internal/source_map/prepare_stack_trace.js
+++ b/lib/internal/source_map/prepare_stack_trace.js
@@ -88,7 +88,7 @@ const prepareStackTrace = (globalThis, error, trace) => {
}
// Construct call site name based on: v8.dev/docs/stack-trace-api:
const fnName = t.getFunctionName() ?? t.getMethodName();
- const originalName = `${t.getTypeName() !== 'global' ?
+ const originalName = `${(t.getTypeName() !== 'global' && t.getTypeName() !== null) ?
`${t.getTypeName()}.` : ''}${fnName || '<anonymous>'}`;
// The original call site may have a different symbol name
// associated with it, use it: |
|
I have cloned a fresh copy of the repo, am currently building and testing const typeName = t.getTypeName();
const namePrefix = typeName && typeName !== 'global' ? `${typeName}.` : '';
const originalName = `${namePrefix}${fnName || '<anonymous>'}`;Is it possible for typeName to be an empty string? Or undefined vs null? This here would cover all I would expect. |
|
I tested locally before making that suggestion - I got either a name or |
|
It seems according to the v8 docs it's either the name or
|
|
using |
|
Hmm if its always null or a truthy string then thats cool to actually reference null there instead |
const typeName = t.getTypeName();
const namePrefix = typeName && typeName !== 'global' ? `${typeName}.` : '';
const originalName = `${namePrefix}${fnName || '<anonymous>'}`;vs const typeName = t.getTypeName();
const namePrefix = typeName !== null && typeName !== 'global' ? `${typeName}.` : '';
const originalName = `${namePrefix}${fnName || '<anonymous>'}`;vs const typeName = t.getTypeName();
const namePrefix = ![null, 'global'].includes(typeName) ? `${typeName}.` : '';
const originalName = `${namePrefix}${fnName || '<anonymous>'}`;What can const typeName = t.getTypeName();
const namePrefix = ![null, 'global'].includes(typeName) ? `${typeName}.` : '';
const originalName = `${namePrefix}${fnName === null ? '<anonymous>' : fnName}`; |
|
(my node build is still building for the first time... you someone else might be able to do a PR quicker) |
yarn build && export $(cat .env | xargs) && node --enable-source-maps esnext/tests/index.js{
reason: /Users/fabiancook/src/virtualstate/fringe/src/tests/throw.tsx:5
throw new Error();
^
Error
at Throw1 (/Users/fabiancook/src/virtualstate/fringe/src/tests/throw.tsx:5:11)
at Object.[Symbol.asyncIterator] (/Users/fabiancook/src/virtualstate/fringe/src/component.ts:32:22)
at AsyncGenerator.next (<anonymous>)
at childrenSettledGeneratorInner (/Users/fabiancook/src/virtualstate/fringe/src/children.ts:135:24)
at childrenSettledGeneratorInner.next (<anonymous>)
at childrenSettledGeneratorInner (/Users/fabiancook/src/virtualstate/fringe/src/children.ts:131:14)
at childrenSettledGeneratorInner.next (<anonymous>)
at childrenSettledGenerator (/Users/fabiancook/src/virtualstate/fringe/src/children.ts:112:22)
at childrenSettledGenerator.next (<anonymous>)
at <anonymous> (/Users/fabiancook/src/virtualstate/fringe/src/children.ts:187:28),
status: 'rejected'
}
Can confirm this fixes my original issue. |
|
Thanks @fabiancook this looks good :) Can you please add a test? |
|
Yep for sure! If there is any pointers on how to go about defining source map tests without including typescript specific source maps that would be good. Is there a way I can generate this specific problem as a source map object? I'll be adding this test tomorrow evening most likely. |
|
@fabiancook sure, if you look at Benjamin (Coe)'s work there are fixtures (the fixtures can come from TypeScript that's fine I think) as such https://github.com/nodejs/node/tree/master/test/fixtures/source-map You can see an example here: https://github.com/nodejs/node/pull/39025/files Basically:
|
|
In my tests I am including export async function Throw() {
throw new Error(message)
}
await Throw();This now will show as Error: Message 0.3702386924909997\n' +
at Throw (/Users/fabiancook/src/node/test/fixtures/source-map/throw-async.ts:4:9)But should this not be instead showing as Error: Message 0.3702386924909997\n' +
at async Throw (/Users/fabiancook/src/node/test/fixtures/source-map/throw-async.ts:4:9)I see later in the stack at async Promise.all (index 0) |
|
Hello 👋 as I'm wont to be, was quite busy the last few weeks and missed this thread. Looks like we got to the bottom of things, and have some thoughts about bug fixes. Please flag me if you need review, or help making the patch (feel free to reach out on Twitter, [at]BenjaminCoe) if I'm ever slow to respond to GitHub notifications 👍 |
Fixes: #42417 PR-URL: #42522 Reviewed-By: Benjamin Gruenbaum <[email protected]> Reviewed-By: James M Snell <[email protected]>
|
Off the back of this, I hadn't fixed while I was in there, but should I had tried But it does not show as const asyncPrefix = t.isAsync() ? 'async ' : 'sync ';
const namePrefix = typeName !== null && typeName !== 'global' ? `${typeName}.` : '';
const originalName = `${asyncPrefix}${namePrefix}${fnName || '<anonymous>'}`; actual: '/Users/fabiancook/src/virtualstate/node/test/fixtures/source-map/throw-async.ts:4\n' +
' throw new Error(message)\n' +
' ^\n' +
'\n' +
'Error: Message 0.4547369137955799\n' +
' at sync Throw (/Users/fabiancook/src/virtualstate/node/test/fixtures/source-map/throw-async.ts:4:9)\n' +
' at sync <anonymous> (/Users/fabiancook/src/virtualstate/node/test/fixtures/source-map/throw-async.ts:7:7)\n' +
' at ModuleJob.run (node:internal/modules/esm/module_job:198:25)\n' +
' at async Promise.all (index 0)\n' +
' at async ESMLoader.import (node:internal/modules/esm/loader:409:24)\n' +
' at async loadESM (node:internal/process/esm_loader:85:5)\n' +
' at async handleMainPromise (node:internal/modules/run_main:61:12)\n' +
'\n' +
'Node.js v18.0.0-pre\n',
expected: /at async Throw \([^)]+throw-async\.ts:4:9\)/,
operator: 'match'I would have expected const message = 'Message ' + Math.random();
export async function Throw() {
throw new Error(message);
}
await Throw();When would we ever see |
Is there any chance you compiled that to a low target without async/await and the async bit only exists in the source map? If so it should probably be extracted from there? The CallSite probably has no knowledge of that at this point. |
|
Yeah there is a good chance I am targeting something without async support, its the default tsc options I used outside of defining module + esnext @cspotcode you mentioned you had some independent tests, do any cover async as well? |
|
It's probably worth it to open a new issue with this other issue/feature-request/bug for |
Fixes: nodejs#42417 PR-URL: nodejs#42522 Reviewed-By: Benjamin Gruenbaum <[email protected]> Reviewed-By: James M Snell <[email protected]>
Fixes: #42417 PR-URL: #42522 Reviewed-By: Benjamin Gruenbaum <[email protected]> Reviewed-By: James M Snell <[email protected]>
|
The benchmark I linked does a really simple check for async stack trace handling, but it's not a rigorous test. That's all I have. |
Fixes: nodejs#42417 PR-URL: nodejs#42522 Reviewed-By: Benjamin Gruenbaum <[email protected]> Reviewed-By: James M Snell <[email protected]>
Fixes: #42417 PR-URL: #42522 Reviewed-By: Benjamin Gruenbaum <[email protected]> Reviewed-By: James M Snell <[email protected]>
Fixes: #42417 PR-URL: #42522 Reviewed-By: Benjamin Gruenbaum <[email protected]> Reviewed-By: James M Snell <[email protected]>
Fixes: #42417 PR-URL: #42522 Reviewed-By: Benjamin Gruenbaum <[email protected]> Reviewed-By: James M Snell <[email protected]>
Fixes: #42417 PR-URL: #42522 Reviewed-By: Benjamin Gruenbaum <[email protected]> Reviewed-By: James M Snell <[email protected]>
Fixes: nodejs/node#42417 PR-URL: nodejs/node#42522 Reviewed-By: Benjamin Gruenbaum <[email protected]> Reviewed-By: James M Snell <[email protected]>
|
You probably didn't wait for a spin around the event loop before throwing,
so you were throwing synchronously.
If you're unclear on the output you get from tsc, just test it manually:
run the compiler and look at the output in your editor. Target: esnext
will emit async functions.
The benchmark I linked here tests async:
evanw/node-source-map-support#122 (comment)
…On Mon, Apr 4, 2022, 6:23 AM Benjamin Gruenbaum ***@***.***> wrote:
It's probably worth it to open a new issue with this other
issue/feature-request/bug for async in the ttrace
—
Reply to this email directly, view it on GitHub
<#42417 (comment)>, or
unsubscribe
<https://github.com/notifications/unsubscribe-auth/AAC35OCJQ3DKXSJL33HZ4QTVDK7KPANCNFSM5RHAAZOA>
.
You are receiving this because you were mentioned.Message ID:
***@***.***>
|
Version
v17.4.0
Platform
Darwin Mac-mini.local 21.2.0 Darwin Kernel Version 21.2.0: Sun Nov 28 20:29:10 PST 2021; root:xnu-8019.61.5~1/RELEASE_ARM64_T8101 arm64
Subsystem
No response
What steps will reproduce the bug?
You will see the last log being:
or the smaller case:
Logs
If I run this same code with deno, I do not see null
How often does it reproduce? Is there a required condition?
No response
What is the expected behavior?
null does not show
What do you see instead?
null shows
Additional information
I'm reporting this because I expect showing null is not intentional.
The text was updated successfully, but these errors were encountered: