Overriding `Module.print` does not work with `-sNODERAWFS` / `-sFORCE_FILESYSTEM`

[kleisauke]

Description:
It looks like Module.print does not always work with -sNODERAWFS. A simple printf("hello, world!\n"); program works, but when the program actually makes use of the file system (e.g. doing a fopen() call), Module.print is ignored and the output is directly written to the terminal. Forcing the full file system with -sFORCE_FILESYSTEM also reproduces this with a simple printf() call.

Reproduction:
See commit kleisauke@6dac36a for a test case, with that just run:

$ ./test/runner other.test_noderawfs_override_standard_streams -v

Or if you prefer a standalone example:

$ cat <<EOT >> pre.js
let stdout = '';
let stderr = '';
Module['print'] = function(text) {
  stdout += text;
}
Module['printErr'] = function(text) {
  stderr += text;
}
Module['postRun'] = function() {
    assert(stderr == '', 'stderr should be empty. \\n' +
        'stderr: \\n' + stderr);
    assert(stdout.startsWith('hello, world!'), 'stdout should start with the famous greeting. \\n' +
        'stdout: \\n' + stdout);
}
EOT
$ emcc test/hello_world.c -o hello_world.js -sNODERAWFS -sFORCE_FILESYSTEM --pre-js pre.js
$ node hello_world.js

Expected behavior:
Overriding Module.print should work and nothing should print to the terminal.

Actual behavior:

hello, world!
/home/kleisauke/hello_world.js:162
      throw ex;
      ^

RuntimeError: Aborted(Assertion failed: stdout should start with the famous greeting. 
stdout: 
)
    at abort (/home/kleisauke/hello_world.js:947:11)
    at assert (/home/kleisauke/hello_world.js:478:5)
    at Module.postRun (/home/kleisauke/hello_world.js:35:5)
    at callRuntimeCallbacks (/home/kleisauke/hello_world.js:1196:26)
    at postRun (/home/kleisauke/hello_world.js:796:3)
    at doRun (/home/kleisauke/hello_world.js:5324:5)
    at run (/home/kleisauke/hello_world.js:5337:5)
    at runCaller (/home/kleisauke/hello_world.js:5245:19)
    at removeRunDependency (/home/kleisauke/hello_world.js:912:7)
    at receiveInstance (/home/kleisauke/hello_world.js:1079:5)

Version of emscripten/emsdk:

emcc (Emscripten gcc/clang-like replacement + linker emulating GNU ld) 3.1.19 (a5f7b1c9a1c74a830bebedc122d204800ce8dff9)
clang version 16.0.0 (https://github.com/llvm/llvm-project 30171e76f0e5ea8037bc4d1450dd3e12af4d9938)
Target: wasm32-unknown-emscripten
Thread model: posix
InstalledDir: /home/kleisauke/emsdk/upstream/bin

(but probably older versions also have the same bug)

Downstream issue: kleisauke/wasm-vips#23

[kleisauke]

Eventually, WasmFS would fix this, so please don't spend too much time on this. Though, for WasmFS it looks like a printf() in a pthread would always be printed on the terminal, see for example:

$ cat <<EOT > test.c
#include <stdio.h>

int main() {
  // stderr
  fprintf(stderr, "hello, world!\n");
  // stdout
  printf("hello, world!\n");
  return 0;
}
EOT
$ cat <<EOT > main.js
const Test = require('./test.js');

async function main() {
  await Test({
    // In an ideal world, nothing would be printed on the terminal.
    print: (text) => {},
    printErr: (text) => {},
  });
}
main();
EOT
# pthread usage
$ emcc -O3 test.c -o test.js -s MODULARIZE=1 -sEXPORT_NAME=Test -sWASMFS -sEXIT_RUNTIME -pthread -sPROXY_TO_PTHREAD
$ node --experimental-wasm-threads --experimental-wasm-bulk-memory main.js
hello, world!
hello, world!
# Non-pthread usage
$ emcc -O3 test.c -o test.js -s MODULARIZE=1 -sEXPORT_NAME=Test -sWASMFS -sEXIT_RUNTIME
$ node main.js

Should I open a new issue for that?

[kleisauke]

The above mentioned WasmFS issue could be resolved by doing:

--- a/src/worker.js
+++ b/src/worker.js
@@ -136,6 +136,11 @@ self.onmessage = (e) => {
       Module['dynamicLibraries'] = e.data.dynamicLibraries;
 #endif
 
+      {{{ makeAsmImportsAccessInPthread('print') }}} = (text) =>
+        postMessage({cmd: 'print', text: text, threadId: Module['_pthread_self']()});
+      {{{ makeAsmImportsAccessInPthread('printErr') }}} = (text) => 
+        postMessage({cmd: 'printErr', text: text, threadId: Module['_pthread_self']()});
+
       {{{ makeAsmImportsAccessInPthread('wasmMemory') }}} = e.data.wasmMemory;
 
 #if LOAD_SOURCE_MAP

To ensure that the Module['print'] and Module['printErr'] functions exist in a pthread and postMessage it back to the main thread:

emscripten/src/library_pthread.js

Lines 274 to 277 in 85412cb

	} else if (cmd === 'print') {
	out('Thread ' + d['threadId'] + ': ' + d['text']);
	} else if (cmd === 'printErr') {
	err('Thread ' + d['threadId'] + ': ' + d['text']);

Alternatively, we could proxy the _emscripten_out and _emscripten_err functions back to the main thread by doing this:

--- a/src/library.js
+++ b/src/library.js
@@ -3355,6 +3355,7 @@ mergeInto(LibraryManager.library, {
   },
 
   _emscripten_out__sig: 'vp',
+  _emscripten_out__proxy: 'sync',
   _emscripten_out: function(str) {
 #if ASSERTIONS
     assert(typeof str == 'number');
@@ -3363,6 +3364,7 @@ mergeInto(LibraryManager.library, {
   },
 
   _emscripten_err__sig: 'vp',
+  _emscripten_err__proxy: 'sync',
   _emscripten_err: function(str) {
 #if ASSERTIONS
     assert(typeof str == 'number');

I'm not sure what's preferred. Perhaps there's a better way to resolve this?

[kripken]

To make sure I understand - is the issue that the user overrides Module.print, but that only happens on the main thread, as worker JS contexts don't run that user JS code that sets Module.print (in fact it might be connected to the HTML, which is only on the main thread). So printing on workers uses the default print path. Is that right?

I think that is a real issue, if so. On the one hand, proxying is generally the right thing to do, as in the last diff. Can it be async, though? That would avoid possible deadlocks. On the other hand, 99% of the time Module.print is not overridden, so the proxying overhead would be wasted... but trying to avoid it is tricky.

[kleisauke]

Yes, exactly. I noticed that onAbort had also a similar issue:

emscripten/src/preamble.js

Lines 458 to 467 in fc3a217

	#if USE_PTHREADS
	// When running on a pthread, none of the incoming parameters on the module
	// object are present. The `onAbort` handler only exists on the main thread
	// and so we need to proxy the handling of these back to the main thread.
	// TODO(sbc): Extend this to all such handlers that can be passed into on
	// module creation.
	if (ENVIRONMENT_IS_PTHREAD) {
	postMessage({ 'cmd': 'onAbort', 'arg': what});
	} else
	#endif

I just opened PR #17925 for this.

[kripken]

I believe this was fixed by #17925 ? Please reopen if not.