fprintf is non-thread-safe

[emaxx-google]

Emscripten's implementation of fprintf isn't thread-safe in the sense that lines printed from different threads may interleave with each other, producing merged/corrupted messages in the result.

For example, when running the following program built under Emscripten:

#include <cstdio>
#include <string>
#include <thread>
void thread_main() {
  std::string msg(100, 'a');
  for (int i = 0; i < 10000; ++i)
    fprintf(stderr, "%s\n", msg.c_str());
}
int main() {
  std::thread t1(thread_main);
  std::thread t2(thread_main);
  t1.join();
  t2.join();
}

with piping its result through sort -u, it can be seen that besides the expected 100-character lines there are often 200-/300-character ones - obviously, the lines printed from different threads got collapsed and merged together.

This behavior doesn't seem to conform to the POSIX specification:

All functions that reference (FILE *) objects, except those with names ending in _unlocked, shall behave as if they use flockfile() and funlockfile() internally to obtain ownership of these (FILE *) objects.
(https://pubs.opengroup.org/onlinepubs/9699919799/functions/flockfile.html)

The same program compiled using the normal g++ with the standard libc always produces only the expected 100-line characters on my Linux machine.

[emaxx-google]

BTW, it's not just a "cosmetic" corruption of strings, since in case the printed messages are UTF-8, this issue causes them to sometimes become incorrect UTF strings, resulting in making the messages undecipherable and hitting some internal error logs and assertions in Emscripten code.

[emaxx-google]

Additionally, after running this program several hundreds of times it failed with the following memory corruption error:

Pthread aborting at Error                                                                                                                                                        
    at abort (eval at globalEval (a.out.worker.js:211:10), <anonymous>:1490:70)                                     
    at Object.checkStackCookie (eval at globalEval (a.out.worker.js:211:10), <anonymous>:1269:46)                   
    at onmessage (a.out.worker.js:120:35)
    at MessagePort.<anonymous> (a.out.worker.js:199:5)
    at MessagePort.emit (events.js:315:20)
    at MessagePort.onmessage (internal/worker/io.js:78:8)
    at MessagePort.exports.emitMessage (internal/per_context/messageport.js:11:10)
pthread sent an error! undefined:undefined: abort(Runtime error: The application has corrupted its heap memory area (address zero)!) at Error
    at jsStackTrace (eval at globalEval (a.out.worker.js:211:10), <anonymous>:2125:19)
    at stackTrace (eval at globalEval (a.out.worker.js:211:10), <anonymous>:2142:16)
    at abort (eval at globalEval (a.out.worker.js:211:10), <anonymous>:1497:44)
    at Object.checkStackCookie (eval at globalEval (a.out.worker.js:211:10), <anonymous>:1269:46)
    at onmessage (a.out.worker.js:120:35)
    at MessagePort.<anonymous> (a.out.worker.js:199:5)
    at MessagePort.emit (events.js:315:20)
    at MessagePort.onmessage (internal/worker/io.js:78:8)
    at MessagePort.exports.emitMessage (internal/per_context/messageport.js:11:10)
Proxied main thread 0xa045c0 finished with return code 0. EXIT_RUNTIME=1 set, quitting process.
exitProcess requested by worker
main thead called exit: noExitRuntime=undefined
Runtime error: The application has corrupted its heap memory area (address zero)!
a.out.js:145
      throw ex;

(I don't know if it's related to fprintf or is a separate pthreads issue.)

[emaxx-google]

Hello, is there any update on this issue? It sounds unfortunate that the print debugging, even recommended as the first debugging means by the official doc (https://emscripten.org/docs/porting/Debugging.html#manual-print-debugging) is actually causing additional issues by itself.

BTW, I ran the repro snippet quoted above under 2.0.13, and after a few runs I got an error about invalid UTF, despite that all strings printed by the program are ASCII:

Invalid UTF-8 leading byte 0x-1 encountered when deserializing a UTF-8 string on the asm.js/wasm heap to a JS string!

So the memory corruption errors quoted above might be true, as this would at least explain how printed ASCII strings could turn into invalid UTF-8.

[kleisauke]

Thanks for the reproducer! It seems that an initialization was missing for the stdin-, stdout-, stderr lock. Commit d5d5f69 (see work-in-progress PR #13007) fixes this for me.

I'll look into splitting that patch into a separate PR.

[emaxx-google]

That's great news; thanks for looking into this!

[emaxx-google]

Hello, is there any timeline for when those fixes (PR #13007 or it follow-ups) can be landed?

For the context, we're looking into rolling out a Wasm version of an existing Chrome extension that previously used multi-threaded NaCl modules. This issue is one of blockers, since it implies that normal debug logs to stdout/stderr can cause random crashes in the field (see the memory corruption log quoted above).

[kleisauke]

Sorry for the delay. I'm a bit out of bandwidth lately, it would be great if one of the Emscripten maintainers could land that separately, otherwise I'll take a look at it this week.

As a possible workaround, you could use emscripten_log, which does not exhibit this behavior, afaik.

[kripken]

I had some time today and opened a PR for your fixes for this issue @kleisauke , #13837 . Verified as working perfectly, thanks!

[emaxx-google]

Hello, can the same issue happen to other string streams (like std::ostringstream)?
I'm wondering because I'm investigating some memory corruption issues, and ASan points me to internals of std::basic_ostream::operator<<(unsigned long long) (with the stream being stack-allocated in one of upper frames, so that it's guaranteed to still exist).