Error stacks in log includes null.thing instead of just thing

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?

git clone git@github.com:virtualstate/focus.git
cd focus
git checkout 07998653ea604a44e15d31e66fa4e3e6c72c06be
yarn
yarn test

You will see the last log being:

  [
    { value: [Object], status: 'fulfilled' },
    {
      reason: /Users/fabiancook/src/virtualstate/focus/src/tests/throw.tsx:5
          throw new Error();
                ^
      
      Error
          at null.Throw1 (/Users/fabiancook/src/virtualstate/focus/src/tests/throw.tsx:5:11)
          at Object.[Symbol.asyncIterator] (/Users/fabiancook/src/virtualstate/focus/src/component.ts:32:22)
          at AsyncGenerator.next (<anonymous>)
          at null.childrenSettledGeneratorInner (/Users/fabiancook/src/virtualstate/focus/src/children.ts:135:24)
          at childrenSettledGeneratorInner.next (<anonymous>)
          at null.childrenSettledGeneratorInner (/Users/fabiancook/src/virtualstate/focus/src/children.ts:131:14)
          at childrenSettledGeneratorInner.next (<anonymous>)
          at null.childrenSettledGenerator (/Users/fabiancook/src/virtualstate/focus/src/children.ts:112:22)
          at childrenSettledGenerator.next (<anonymous>)
          at null.<anonymous> (/Users/fabiancook/src/virtualstate/focus/src/children.ts:187:28),
      status: 'rejected'
    }
  ]
]

or the smaller case:

try {
    async function Throw1() {
        throw new Error();
    }
    await Throw1();
} catch (error) {
    console.error(error)
}

Logs

Error
    at null.Throw1 (/Users/fabiancook/src/virtualstate/fringe/src/tests/throw.tsx:5:11)
    at null.<anonymous> (/Users/fabiancook/src/virtualstate/fringe/src/tests/throw.tsx:59:11)

If I run this same code with deno, I do not see null

yarn test:deno

  [
    {
      value: { source: "child1", options: [Object], children: [Object] },
      status: "fulfilled"
    },
    {
      reason: Error
    at Throw1 (file:///Users/fabiancook/src/virtualstate/fringe/esnext/tests/throw.js:4:11)
    at Object.[Symbol.asyncIterator] (file:///Users/fabiancook/src/virtualstate/fringe/esnext/component.js:25:28)
    at AsyncGenerator.next (<anonymous>)
    at childrenSettledGeneratorInner (file:///Users/fabiancook/src/virtualstate/fringe/esnext/children.js:62:30)
    at childrenSettledGeneratorInner.next (<anonymous>)
    at childrenSettledGeneratorInner (file:///Users/fabiancook/src/virtualstate/fringe/esnext/children.js:56:20)
    at childrenSettledGeneratorInner.next (<anonymous>)
    at childrenSettledGenerator (file:///Users/fabiancook/src/virtualstate/fringe/esnext/children.js:43:26)
    at childrenSettledGenerator.next (<anonymous>)
    at file:///Users/fabiancook/src/virtualstate/fringe/esnext/children.js:94:34,
      status: "rejected"
    }
  ]
]

Error
    at Throw1 (file:///Users/fabiancook/src/virtualstate/fringe/esnext/tests/throw.js:53:15)
    at file:///Users/fabiancook/src/virtualstate/fringe/esnext/tests/throw.js:55:11

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.

🤦🏻

I believe this is just something to do with the source map. Disabling shows the correct error stack.

  [
    { value: [Object], status: 'fulfilled' },
    {
      reason: Error
          at Throw1 (file:///Users/fabiancook/src/virtualstate/fringe/esnext/tests/throw.js:4:11)
          at Object.[Symbol.asyncIterator] (file:///Users/fabiancook/src/virtualstate/fringe/esnext/component.js:25:28)
          at AsyncGenerator.next (<anonymous>)
          at childrenSettledGeneratorInner (file:///Users/fabiancook/src/virtualstate/fringe/esnext/children.js:62:30)
          at childrenSettledGeneratorInner.next (<anonymous>)
          at childrenSettledGeneratorInner (file:///Users/fabiancook/src/virtualstate/fringe/esnext/children.js:56:20)
          at childrenSettledGeneratorInner.next (<anonymous>)
          at childrenSettledGenerator (file:///Users/fabiancook/src/virtualstate/fringe/esnext/children.js:43:26)
          at childrenSettledGenerator.next (<anonymous>)
          at file:///Users/fabiancook/src/virtualstate/fringe/esnext/children.js:94:34,
      status: 'rejected'
    }
  ]
]

Will leave open and let someone else decide if it is still relevant to investigate for source maps, or to leave as is.

@fabiancook

@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/tsc

throw1.ts:

async function Throw1() {
    throw new Error();
}

try {
    await Throw1();
} catch (error) {
    console.log(error);
}

export default 1;

throw1.js:

async function Throw1() {
    throw new Error();
}
try {
    await Throw1();
}
catch (error) {
    console.log(error);
}
export default 1;
//# sourceMappingURL=throw1.js.map

throw1.js.map:

{"version":3,"file":"throw1.js","sourceRoot":"","sources":["../../src/tests/throw1.tsx"],"names":[],"mappings":"AAAA,KAAK,UAAU,MAAM;IACjB,MAAM,IAAI,KAAK,EAAE,CAAC;AACtB,CAAC;AAED,IAAI;IACA,MAAM,MAAM,EAAE,CAAC;CAClB;AAAC,OAAO,KAAK,EAAE;IACZ,OAAO,CAAC,GAAG,CAAC,KAAK,CAAC,CAAC;CACtB;AAED,eAAe,CAAC,CAAC"}

node --enable-source-maps esnext/tests/throw1.js:

/Users/fabiancook/src/virtualstate/fringe/src/tests/throw1.tsx:2
    throw new Error();
          ^

Error
    at null.Throw1 (/Users/fabiancook/src/virtualstate/fringe/src/tests/throw1.tsx:2:11)
    at null.<anonymous> (/Users/fabiancook/src/virtualstate/fringe/src/tests/throw1.tsx:6:11)
    at ModuleJob.run (node:internal/modules/esm/module_job:195:25)
    at async Promise.all (index 0)
    at async ESMLoader.import (node:internal/modules/esm/loader:337:24)
    at async loadESM (node:internal/process/esm_loader:88:5)
    at async handleMainPromise (node:internal/modules/run_main:61:12)

node esnext/tests/throw1.js:

Error
    at Throw1 (file:///Users/fabiancook/src/virtualstate/fringe/esnext/tests/throw1.js:2:11)
    at file:///Users/fabiancook/src/virtualstate/fringe/esnext/tests/throw1.js:5:11
    at ModuleJob.run (node:internal/modules/esm/module_job:195:25)
    at async Promise.all (index 0)
    at async ESMLoader.import (node:internal/modules/esm/loader:337:24)
    at async loadESM (node:internal/process/esm_loader:88:5)
    at async handleMainPromise (node:internal/modules/run_main:61:12)

What is a native node source map vs what I have here? I see in the documentation

Enable Source Map v3 support for stack traces.

The above has {"version":3...} so I am hoping this is what you're looking for.

@bcoe

@bcoe hmm, the null should probably be filtered here?

It also omits async, so it doesn't seem to handle async stack traces correctly.

$ 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 source-map-support:

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 null.

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 null - let me read the code

It seems according to the v8 docs it's either the name or null: .

This is the name of the function stored in the constructor field of this, if available, otherwise the object’s [[Class]] internal property.

using typeName && ... is following the same as fnName || ...

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 fnName be?

const typeName = t.getTypeName();
const namePrefix = ![null, 'global'].includes(typeName) ? `${typeName}.` : '';
const originalName = `${namePrefix}${fnName === null ? '<anonymous>' : fnName}`;

lib: source maps filter null prefix

Off the back of this, I hadn't fixed while I was in there, but should Throw not also show async ? Is there relevant documentation on what I should be using from v8 to be able to add that to the namePrefix as well?

I had tried t.isAsync() as per the documentation here: https://v8.dev/docs/stack-trace-api#customizing-stack-traces

But it does not show as async still (see sync showing instead of async)

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 isAsync to return true, since it both uses async, and was await'd (explicitly mentioned in the v8 docs)

const message = 'Message ' + Math.random();
export async function Throw() {
    throw new Error(message);
}
await Throw();

When would we ever see isAsync as true from user land, if this is not its usage?

I would have expected isAsync to return true, since it both uses async, and was await'd (explicitly mentioned in the v8 docs)

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.

@cspotcode

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 async in the ttrace

lib: source maps filter null prefix

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.

lib: source maps filter null prefix

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: ***@***.***>

Navigation Menu

Repository navigation

Error stacks in log includes null.thing instead of just thing #42417

Version

Platform

Subsystem

What steps will reproduce the bug?

How often does it reproduce? Is there a required condition?

What is the expected behavior?

What do you see instead?

Additional information

8 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Error stacks in log includes null.thing instead of just thing #42417

Description

Version

Platform

Subsystem

What steps will reproduce the bug?

How often does it reproduce? Is there a required condition?

What is the expected behavior?

What do you see instead?

Additional information

Activity

fabiancook commented on Mar 21, 2022

benjamingr commented on Mar 21, 2022

fabiancook commented on Mar 22, 2022

benjamingr commented on Mar 22, 2022

cspotcode commented on Mar 25, 2022

cspotcode commented on Mar 25, 2022

fabiancook commented on Mar 30, 2022

benjamingr commented on Mar 30, 2022

benjamingr commented on Mar 30, 2022

fabiancook commented on Mar 30, 2022

benjamingr commented on Mar 30, 2022

benjamingr commented on Mar 30, 2022

fabiancook commented on Mar 30, 2022

fabiancook commented on Mar 30, 2022

fabiancook commented on Mar 30, 2022

8 remaining items

fabiancook commented on Apr 4, 2022

benjamingr commented on Apr 4, 2022

fabiancook commented on Apr 4, 2022

benjamingr commented on Apr 4, 2022

cspotcode commented on Apr 20, 2022

cspotcode commented on Oct 11, 2022

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions