5.8mb contents of obfuscated wasm module printed when exception thrown elsewhere in program

[dvtate]

Version

v18.3.0

Platform

Linux archbook 5.18.3-arch1-1 #1 SMP PREEMPT_DYNAMIC Thu, 09 Jun 2022 16:14:10 +0000 x86_64 GNU/Linux

Subsystem

No response

What steps will reproduce the bug?

Please see this issue thread: emscripten-core/emscripten#17228

A realistic example is done as follows:

$ echo "{}" > package.json
$ npm install binaryen
$ cat > test.mjs
// Appears to be imported in a new thread?
import binaryen from 'binaryen';

// Never seen
console.warn('important debugging message!!');

throw new Error('fatal');

$ node test.mjs
important debugging message!!
[... 5.8 mb contents of node_modules/binaryen/index.js output to stderr ...]
[ 6 new lines ]
Error: fatal
    at file:///home/tate/Desktop/emscr-bug/test.mjs:7:7

Node.js v18.3.0
$ 

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

Consistently reproducable. I even remember experienceing this exact bug as far back as 2020 (nodejs v14+)

What is the expected behavior?

I'm assuming that it's importing the module concurrently with the main thread if that's the case than on error only the thread that errored should have it's code highlighted, or at least the code highlighted code should be truncated to where it doesn't take several seconds to print

What do you see instead?

5.8mb of obfuscated javascript which burries the debugging message I had written

Additional information

Relevant thread: emscripten-core/emscripten#17228

[lastmjs]

Hi I am running into what seems like the exact same problem. I added some context including a very simple reproducible example in the emscripten thread here: emscripten-core/emscripten#17228 (comment)

@dvtate did you ever find a workaround for this?

[dvtate]

@lastmjs IIRC the problem occurs when there's an uncaught exception. So maybe if you catch all the exceptions (and maybe print them differently?)

[lastmjs]

Unfortunately that does not help, I've tried to do this for example like this:

process.on('uncaughtException', () => {
    console.log('uncaughtException')
});

process.on('unhandledRejection', () => {
    console.log('unhandledRejection')
});

import "binaryen";

throw new Error("Should not see all of the code above");

The wall of text still comes.

The best I have found so far is to use --abort-on-uncaught-exception which gets rid of the wall of text, but has an unfortunate scary-looking stack trace below the error.

[lastmjs]

BTW @RedYetiDev I'm not sure how much this issue has to do with Wasm. The binaryen.js library is a very large file of minified JS, and that is what is printed to the terminal.

[lastmjs]

Based on the information in the other issues and what I've found, the root of the problem seems to be with Node.js (for example: AssemblyScript/binaryen.js#94 (comment)).

[dvtate]

@RedYetiDev the problem is that nodejs always prints out the entire line that the error originates from. For minified code this single line could be very, very big (and unreadable). Node.js should truncate code snippets printed out in error messages.

[RedYetiDev]

That seems to be working as intended, but I'd love a second opinion.

[romdotdog]

Why is dumping an entire minified file into the stack trace considered as Node.js "working as intended"? "Working as intended" should be truncating the line because nobody needs the entire source code to be print out every stack trace.

[RedYetiDev]

Keep in mind this is all my opinion, so someone else could always disagree.

The way I see it is: if the source code is minified into one line, that's the line that will be printed. The stack trace always printed where the error came from. Whether the error can from a normal line(s) or a minified one, the line(s) where it came from will always be printed.

[RedYetiDev]

FWIW repro-exists:

const fs = require('fs');

// Setup
fs.writeFileSync('index.js', 
    `"${'a'.repeat(10000)}"; throw new Error("Error!")`
)

// Run
require('./index.js')

[romdotdog]

Whether the error can from a normal line(s) or a minified one, the line(s) where it came from will always be printed.

How is this helpful? When would a Node.js developer ever need a line tens of thousands of characters long printed in their terminal as part of a stack trace? It doesn't help with debugging (and actually impedes it), which defeats the point of a stack trace.

[RedYetiDev]

If you think you have an improvement, feel free to submit a PR.

[CountBleck]

the entire line that the error originates from.

Correction: the error doesn't even originate from the line that's reported. In fact, as you can see in @dvtate's original example and @lastmjs's similar example, the error is thrown in a completely separate file.

That seems to be working as intended, but I'd love a second opinion.

To say that users would like to see multiple screenfuls of minified output is a dubious assertion, but that's not the real issue here. An error is being thrown from one file, but the line that's printed is from another file entirely (the stack trace is correct though). The fact that the line happens to be megabytes long is just a further inconvenience.

Anyways, in case it's useful, I'd like to mention that --enable-source-maps used to fix the problem, but it stopped working between v16.17.1 and v16.18.0.

[RedYetiDev]

It appears we were discussing two seperate things, maybe there was a miscommunication.

1. Stack Trace with large lines - I think this is working as intended, as no matter the line size, it is the error, and is therefor printed
2. Stack Trace with other lines as the problem - That's weird, so it might not be working as intended, i'll look into it a bit, but the repro-exists label should encourage others to take a look.

[RedYetiDev]

FWIW according to the stack that I tested, the error is from:

file:///XYZ/node_modules/binaryen/index.js:6:764

[CountBleck]

It looks like this is the issue:

process.on("uncaughtException", error => {
    throw error // this line probably shouldn't be printed!
})

throw new Error("hey") // this line isn't what's printed...

Running this prints:

/data/data/com.termux/files/home/guh/x.js:2
    throw error // this line probably shouldn't be printed!
    ^

Error: hey
    at Object.<anonymous> (/data/data/com.termux/files/home/guh/x.js:5:7)
    at Module._compile (node:internal/modules/cjs/loader:1467:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1551:10)
    at Module.load (node:internal/modules/cjs/loader:1282:32)
    at Module._load (node:internal/modules/cjs/loader:1098:12)
    at TracingChannel.traceSync (node:diagnostics_channel:315:14)
    at wrapModuleLoad (node:internal/modules/cjs/loader:215:24)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:158:5)
    at node:internal/main/run_main_module:30:49

Node.js v22.4.1

This makes me wonder if this behavior is intentional (maybe it's a matter of preference, but I'd like the printed line to be based on the stack trace)...

In any case, our particular issue will be resolved soon anyway, by removing the uncaughtException handler.

[RedYetiDev]

So if I understand correctly, the minified file (binaryen) is hooking into the uncaughtException, causing it to be logged?

[CountBleck]

@RedYetiDev That's correct, but this is being done through Emscripten's NODEJS_CATCH_EXIT, so you'll find it in https://github.com/emscripten-core/emscripten

[RedYetiDev]

As you showed, process.on is used to capture and re-throw exceptions, which is why the line is being printed. This behavior IMO is working as intended. If you would like a change, I'd a new issue as a feature request.

I'm not saying this won't change, just that it's not (IMO) a bug, but rather a feature request, so feel free to open a new issue.

[lastmjs]

So...could/should binaryen fix this?

[RedYetiDev]

Whomever added the process.on could change the behavior.

[CountBleck]

@lastmjs the next nightly release will fix your issue