Skip to content

Unexpected Behavior with FORMAT_STACK_TRACE #3736

@AvarianKnight

Description

@AvarianKnight

What happened?

When working on adding source map support for JS I noticed that FORMAT_STACK_TRACE would often times eat an errors.

When using the following test code:

const throw_a_error_plz = (id: number, is_async: boolean) => {
  throw new Error(`${id} ${is_async ? "IS_ASYNC" : ""}`);
}

setImmediate(() => throw_a_error_plz(1,false));
setImmediate(async () => {
  throw_a_error_plz(2, true);
})

setImmediate(() => {
  throw new Error("In a sync setImmediate");
})

setImmediate(async () => {
  throw new Error("Inside of an async setImmediate")
})
[script:sourcemap-tes] SCRIPT ERROR in timer: Error: 1:
[script:sourcemap-tes] > throw_a_error_plz (../server/index.ts:3)
[script:sourcemap-tes] > <unknown> (../server/index.ts:6)
ode:46696) UnhandledPromiseRejectionWarning: Error: 2: IS_ASYNC
    at throw_a_error_plz (@sourcemap-test/dist/server.js:6:9)
    at @sourcemap-test/dist/server.js:10:3
    at Object.callback (citizen:/scripting/v8/timer.js:145:21)
    at onTick (citizen:/scripting/v8/timer.js:171:27)
    at citizen:/scripting/v8/timer.js:270:13
    at Number.__cfx_wrap_3 (citizen:/scripting/v8/main.js:24:12)
    at citizen:/scripting/v8/main.js:30:16
    at citizen:/scripting/v8/timer.js:269:16
(Use `FXServer --trace-warnings ...` to show where the warning was created)
8;5;221m[scrip(node:46696) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
t:s(node:46696) UnhandledPromiseRejectionWarning: Error: 4: Inside of an async setImmediate
    at @sourcemap-test/dist/server.js:16:9
    at Object.callback (citizen:/scripting/v8/timer.js:145:21)
    at onTick (citizen:/scripting/v8/timer.js:171:27)
    at citizen:/scripting/v8/timer.js:270:13
    at Number.__cfx_wrap_3 (citizen:/scripting/v8/main.js:24:12)
    at citizen:/scripting/v8/main.js:30:16
    at citizen:/scripting/v8/timer.js:269:16
ourc(node:46696) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2)
emap-tes]
[    c-scripting-core] Ate FORMAT_STACK_TRACE error!

When I disable the g_suppressErrors this didn't happen anymore (quite obviously)

[script:sourcemap-tes] SCRIPT ERROR in timer: Error: 1:
[script:sourcemap-tes] > throw_a_error_plz (../server/index.ts:3)
[script:sourcemap-tes] > <unknown> (../server/index.ts:6)
[script(node:30460) UnhandledPromiseRejectionWarning: Error: 2: IS_ASYNC
    at throw_a_error_plz (@sourcemap-test/dist/server.js:6:9)
    at @sourcemap-test/dist/server.js:10:3
    at Object.callback (citizen:/scripting/v8/timer.js:145:21)
    at onTick (citizen:/scripting/v8/timer.js:171:27)
    at citizen:/scripting/v8/timer.js:270:13
    at Number.__cfx_wrap_3 (citizen:/scripting/v8/main.js:24:12)
    at citizen:/scripting/v8/main.js:30:16
    at citizen:/scripting/v8/timer.js:269:16
(Use `FXServer --trace-warnings ...` to show where the warning was created)
:sourcemap-tes] (node:30460) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
ode:30460) UnhandledPromiseRejectionWarning: Error: 4: Inside of an async setImmediate
    at @sourcemap-test/dist/server.js:16:9
    at Object.callback (citizen:/scripting/v8/timer.js:145:21)
    at onTick (citizen:/scripting/v8/timer.js:171:27)
    at citizen:/scripting/v8/timer.js:270:13
    at Number.__cfx_wrap_3 (citizen:/scripting/v8/main.js:24:12)
    at citizen:/scripting/v8/main.js:30:16
    at citizen:/scripting/v8/timer.js:269:16
0m
(node:30460) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2)
[script:sourcemap-tes] SCRIPT ERROR in timer: Error: 3: In a sync setImmediate
[script:sourcemap-tes] > <unknown> (../server/index.ts:12)

If I were to revert 6e54fc9 and make everything get handled properly by the unhandled promise callback this gets much worse, half of the errors

[script:sourcemap-tes] SCRIPT ERROR in timer: Error: 1:
[script:sourcemap-tes] > throw_a_error_plz (../server/index.ts:3)
[script:sourcemap-tes] > <unknown> (../server/index.ts:6)
[script:sourcemap-tes]
[script:sourcemap-tes] Promise rejection event: 0 Error: 2: IS_ASYNC
[script:sourcemap-tes]     at throw_a_error_plz (@sourcemap-test/dist/server.js:6:9)
[script:sourcemap-tes]     at @sourcemap-test/dist/server.js:10:3
[script:sourcemap-tes]     at Object.callback (citizen:/scripting/v8/timer.js:145:21)
[script:sourcemap-tes]     at onTick (citizen:/scripting/v8/timer.js:171:27)
[script:sourcemap-tes]     at citizen:/scripting/v8/timer.js:270:13
[script:sourcemap-tes]     at Number.__cfx_wrap_3 (citizen:/scripting/v8/main.js:24:12)
[script:sourcemap-tes]     at citizen:/scripting/v8/main.js:30:16
[script:sourcemap-tes]     at citizen:/scripting/v8/timer.js:269:16
[    c-scripting-core] Ate FORMAT_STACK_TRACE error!
[script:sourcemap-tes]
[script:sourcemap-tes] Promise rejection event: 0 Error: 4: Inside of an async setImmediate
[script:sourcemap-tes]     at @sourcemap-test/dist/server.js:16:9
[script:sourcemap-tes]     at Object.callback (citizen:/scripting/v8/timer.js:145:21)
[script:sourcemap-tes]     at onTick (citizen:/scripting/v8/timer.js:171:27)
[script:sourcemap-tes]     at citizen:/scripting/v8/timer.js:270:13
[script:sourcemap-tes]     at Number.__cfx_wrap_3 (citizen:/scripting/v8/main.js:24:12)
[script:sourcemap-tes]     at citizen:/scripting/v8/main.js:30:16
[script:sourcemap-tes]     at citizen:/scripting/v8/timer.js:269:16
[ citizen-server-impl] server thread hitch warning: timer interval of 178 milliseconds
[script:sourcemap-tes] SCRIPT ERROR in promise (unhandled rejection): Error: 2: IS_ASYNC
[script:sourcemap-tes] > throw_a_error_plz (../server/index.ts:3)
[script:sourcemap-tes] > <unknown> (../server/index.ts:8)
[script:sourcemap-tes]
[    c-scripting-core] Ate FORMAT_STACK_TRACE error!

vs with the suppress disabled

[script:sourcemap-tes] SCRIPT ERROR in timer: Error: 1:
[script:sourcemap-tes] > throw_a_error_plz (../server/index.ts:3)
[script:sourcemap-tes] > <unknown> (../server/index.ts:6)
[script:sourcemap-tes]
[script:sourcemap-tes] Promise rejection event: 0 Error: 2: IS_ASYNC
[script:sourcemap-tes]     at throw_a_error_plz (@sourcemap-test/dist/server.js:6:9)
[script:sourcemap-tes]     at @sourcemap-test/dist/server.js:10:3
[script:sourcemap-tes]     at Object.callback (citizen:/scripting/v8/timer.js:145:21)
[script:sourcemap-tes]     at onTick (citizen:/scripting/v8/timer.js:171:27)
[script:sourcemap-tes]     at citizen:/scripting/v8/timer.js:270:13
[script:sourcemap-tes]     at Number.__cfx_wrap_3 (citizen:/scripting/v8/main.js:24:12)
[script:sourcemap-tes]     at citizen:/scripting/v8/main.js:30:16
[script:sourcemap-tes]     at citizen:/scripting/v8/timer.js:269:16
[script:sourcemap-tes] SCRIPT ERROR in timer: Error: 3: In a sync setImmediate
[script:sourcemap-tes] > <unknown> (../server/index.ts:12)
[script:sourcemap-tes]
[script:sourcemap-tes] Promise rejection event: 0 Error: 4: Inside of an async setImmediate
[script:sourcemap-tes]     at @sourcemap-test/dist/server.js:16:9
[script:sourcemap-tes]     at Object.callback (citizen:/scripting/v8/timer.js:145:21)
[script:sourcemap-tes]     at onTick (citizen:/scripting/v8/timer.js:171:27)
[script:sourcemap-tes]     at citizen:/scripting/v8/timer.js:270:13
[script:sourcemap-tes]     at Number.__cfx_wrap_3 (citizen:/scripting/v8/main.js:24:12)
[script:sourcemap-tes]     at citizen:/scripting/v8/main.js:30:16
[script:sourcemap-tes]     at citizen:/scripting/v8/timer.js:269:16
[ citizen-server-impl] server thread hitch warning: timer interval of 216 milliseconds
[script:sourcemap-tes] SCRIPT ERROR in promise (unhandled rejection): Error: 2: IS_ASYNC
[script:sourcemap-tes] > throw_a_error_plz (../server/index.ts:3)
[script:sourcemap-tes] > <unknown> (../server/index.ts:8)
[script:sourcemap-tes]
[script:sourcemap-tes] SCRIPT ERROR in promise (unhandled rejection): Error: 4: Inside of an async setImmediate
[script:sourcemap-tes] > <unknown> (../server/index.ts:16)
[script:sourcemap-tes]

Expected result

Errors to not be eaten by FORMAT_STACK_TRACE

Reproduction steps

const throw_a_error_plz = (id: number, is_async: boolean) => {
  throw new Error(`${id} ${is_async ? "IS_ASYNC" : ""}`);
}

setImmediate(() => throw_a_error_plz(1,false));
setImmediate(async () => {
  throw_a_error_plz(2, true);
})

setImmediate(() => {
  throw new Error("In a sync setImmediate");
})

setImmediate(async () => {
  throw new Error("Inside of an async setImmediate")
})

Importancy

Slight inconvenience

Area(s)

ScRT: JS

Specific version(s)

N/A

Additional information

No response

Metadata

Metadata

Assignees

No one assigned

    Labels

    ScRT: JSIssues/PRs related to the JavaScript scripting runtimebugtriageNeeds a preliminary assessment to determine the urgency and required action

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions