[WASM_WORKERS] Add err/out/dbg overrides like pthreads (#24210)

This change add two pthread debugging features to wasm workers.

1. Under now out/err/dbg all get writting using fs.writeSync rather than
going via console.

2. dbg/err messages get prefixed with the ID of the calling thread.

Author: sbc100

src/lib/libpthread.js

@@ -86,33 +86,8 @@ var LibraryPThread = {
     pthreads: {},
 #if ASSERTIONS
     nextWorkerID: 1,
-    debugInit() {
-      function pthreadLogPrefix() {
-        var t = 0;
-        if (runtimeInitialized && typeof _pthread_self != 'undefined'
-#if EXIT_RUNTIME
-        && !runtimeExited
-#endif
-        ) {
-          t = _pthread_self();
-        }
-        return `w:${workerID},t:${ptrToString(t)}:`;
-      }
-
-      // Prefix all err()/dbg() messages with the calling thread ID.
-      var origDbg = dbg;
-      dbg = (...args) => origDbg(pthreadLogPrefix(), ...args);
-#if PTHREADS_DEBUG
-      // With PTHREADS_DEBUG also prefix all err() messages.
-      var origErr = err;
-      err = (...args) => origErr(pthreadLogPrefix(), ...args);
-#endif
-    },
 #endif
     init() {
-#if ASSERTIONS
-      PThread.debugInit();
-#endif
       if ({{{ ENVIRONMENT_IS_MAIN_THREAD() }}}) {
         PThread.initMainThread();
       }

src/runtime_debug.js

@@ -4,6 +4,29 @@
  * SPDX-License-Identifier: MIT
  */
 
+#if ASSERTIONS || RUNTIME_DEBUG || AUTODEBUG
+var runtimeDebug = true; // Switch to false at runtime to disable logging at the right times
+
+// Used by XXXXX_DEBUG settings to output debug messages.
+function dbg(...args) {
+  if (!runtimeDebug && typeof runtimeDebug != 'undefined') return;
+#if ENVIRONMENT_MAY_BE_NODE && (PTHREADS || WASM_WORKERS)
+  // Avoid using the console for debugging in multi-threaded node applications
+  // See https://github.com/emscripten-core/emscripten/issues/14804
+  if (ENVIRONMENT_IS_NODE) {
+    // TODO(sbc): Unify with err/out implementation in shell.sh.
+    var fs = require('fs');
+    var utils = require('util');
+    var stringify = (a) => typeof a == 'object' ? utils.inspect(a) : a;
+    fs.writeSync(1, args.map(stringify).join(' ') + '\n');
+  } else
+#endif
+  // TODO(sbc): Make this configurable somehow.  Its not always convenient for
+  // logging to show up as warnings.
+  console.warn(...args);
+}
+#endif
+
 #if ASSERTIONS
 
 // Endianness check
@@ -129,6 +152,45 @@ function unexportedRuntimeSymbol(sym) {
   }
 }
 
+#if WASM_WORKERS || PTHREADS
+/**
+ * Override `err`/`out`/`dbg` to report thread / worker information
+ */
+function initWorkerLogging() {
+  function getLogPrefix() {
+#if WASM_WORKERS
+    if (Module['$ww']) {
+      return `ww:${Module['$ww']}:`
+    }
+#endif
+#if PTHREADS
+    var t = 0;
+    if (runtimeInitialized && typeof _pthread_self != 'undefined'
+#if EXIT_RUNTIME
+    && !runtimeExited
+#endif
+    ) {
+      t = _pthread_self();
+    }
+    return `w:${workerID},t:${ptrToString(t)}:`;
+#else
+    return `ww:0:`;
+#endif
+  }
+
+  // Prefix all dbg() messages with the calling thread info.
+  var origDbg = dbg;
+  dbg = (...args) => origDbg(getLogPrefix(), ...args);
+#if RUNTIME_DEBUG
+  // With RUNTIME_DEBUG also prefix all err() messages.
+  var origErr = err;
+  err = (...args) => origErr(getLogPrefix(), ...args);
+#endif
+}
+
+initWorkerLogging();
+#endif
+
 #if ASSERTIONS == 2
 
 var MAX_UINT8  = (2 **  8) - 1;
@@ -186,26 +248,3 @@ function prettyPrint(arg) {
   return arg;
 }
 #endif
-
-#if ASSERTIONS || RUNTIME_DEBUG || AUTODEBUG
-var runtimeDebug = true; // Switch to false at runtime to disable logging at the right times
-
-// Used by XXXXX_DEBUG settings to output debug messages.
-function dbg(...args) {
-  if (!runtimeDebug && typeof runtimeDebug != 'undefined') return;
-#if ENVIRONMENT_MAY_BE_NODE && (PTHREADS || WASM_WORKERS)
-  // Avoid using the console for debugging in multi-threaded node applications
-  // See https://github.com/emscripten-core/emscripten/issues/14804
-  if (ENVIRONMENT_IS_NODE) {
-    // TODO(sbc): Unify with err/out implementation in shell.sh.
-    var fs = require('fs');
-    var utils = require('util');
-    var stringify = (a) => typeof a == 'object' ? utils.inspect(a) : a;
-    fs.writeSync(1, args.map(stringify).join(' ') + '\n');
-  } else
-#endif
-  // TODO(sbc): Make this configurable somehow.  Its not always convenient for
-  // logging to show up as warnings.
-  console.warn(...args);
-}
-#endif

src/shell.js

@@ -377,7 +377,7 @@ if (!ENVIRONMENT_IS_AUDIO_WORKLET)
 #endif // ASSERTIONS
 }
 
-#if ENVIRONMENT_MAY_BE_NODE && PTHREADS
+#if ENVIRONMENT_MAY_BE_NODE && (PTHREADS || WASM_WORKERS)
 // Set up the out() and err() hooks, which are how we can print to stdout or
 // stderr, respectively.
 // Normally just binding console.log/console.error here works fine, but

test/other/test_unoptimized_code_size.js.size

@@ -1 +1 @@
-53602
+53603

test/other/test_unoptimized_code_size_strict.js.size

@@ -1 +1 @@
-51652
+51653

test/test_other.py

@@ -14594,6 +14594,9 @@ def test_wasm_worker_trusted_types(self):
   def test_wasm_worker_terminate(self):
     self.do_runf('wasm_worker/terminate_wasm_worker.c', emcc_args=['-sWASM_WORKERS'])
 
+  def test_wasm_worker_dbg(self):
+    self.do_run_in_out_file_test('wasm_worker/test_wasm_worker_dbg.c', emcc_args=['-sWASM_WORKERS'])
+
   @also_with_minimal_runtime
   def test_wasm_worker_closure(self):
     self.run_process([EMCC, test_file('wasm_worker/lock_async_acquire.c'), '-O2', '-sWASM_WORKERS', '--closure=1'])

test/wasm_worker/hello_wasm_worker.c

@@ -12,7 +12,7 @@ void do_exit() {
 }
 
 void run_in_worker() {
-  emscripten_out("Hello from wasm worker!\n");
+  emscripten_out("Hello from wasm worker!");
   EM_ASM(typeof checkStackCookie == 'function' && checkStackCookie());
   emscripten_wasm_worker_post_function_v(EMSCRIPTEN_WASM_WORKER_ID_PARENT, do_exit);
 }

test/wasm_worker/test_wasm_worker_dbg.c

@@ -0,0 +1,29 @@
+#include <emscripten/emscripten.h>
+#include <emscripten/console.h>
+#include <emscripten/em_asm.h>
+#include <emscripten/wasm_worker.h>
+#include <assert.h>
+
+// This is the code example in site/source/docs/api_reference/wasm_workers.rst
+void do_exit() {
+  emscripten_out("do_exit");
+  emscripten_terminate_all_wasm_workers();
+  emscripten_force_exit(0);
+}
+
+void run_in_worker() {
+  emscripten_out("Hello from wasm worker!");
+  emscripten_err("err from wasm worker");
+  emscripten_dbg("dbg from wasm worker");
+  EM_ASM(typeof checkStackCookie == 'function' && checkStackCookie());
+  emscripten_wasm_worker_post_function_v(EMSCRIPTEN_WASM_WORKER_ID_PARENT, do_exit);
+}
+
+int main() {
+  emscripten_err("err from main thread");
+  emscripten_dbg("dbg from main thread");
+  emscripten_wasm_worker_t worker = emscripten_malloc_wasm_worker(/*stack size: */1024);
+  assert(worker);
+  emscripten_wasm_worker_post_function_v(worker, run_in_worker);
+  emscripten_exit_with_live_runtime();
+}

test/wasm_worker/test_wasm_worker_dbg.out

@@ -0,0 +1,6 @@
+err from main thread
+ww:0: dbg from main thread
+Hello from wasm worker!
+err from wasm worker
+ww:1: dbg from wasm worker
+do_exit