Output is different when connected to a shell vs a pipe

[aykevl]

wasmtime has a different output depending on whether it is run normally or through a pipe (for example, tail).

Test Case

See the wasm.test file here:
wasm-test.zip

Steps to Reproduce

Normal case:

$ wasmtime run test.wasm
line written using C puts
hello world!

Output is redirected to a pipe:

$ wasmtime run test.wasm | tail
line written using C puts

For comparison, I tested the same thing in wasmer and it has the correct (first) output in both cases.

Expected Results

Output should be the same, regardless of where stdout is redirected.

Actual Results

The last line is somehow lost when stdout is redirected to a pipe (in this case, passing it to tail but I've also seen this issue when running from inside Go os/exec).

Versions and Environment

Wasmtime version or commit: wasmtime-cli 17.0.0

Operating system: Linux (Fedora Asahi)

Architecture: aarch64

Extra Info

This is a relatively big test case, I can try to make it smaller if needed.
For example, I've found it reproducible using fwrite("test\n", 5, 1, stdout);.

[alexcrichton]

Thanks for the report! I can reproduce this behavior as well with the uploaded wasm. That being said though I'm not certian that this is a bug in Wasmtime. Through WASMTIME_LOG=trace in the non-piped case (tty stdout) the module is calling fd_write more times than in the piped case. In other words, in the piped case, the module itself isn't even requesting a print. The main difference here is that the module calls fd_fdstat_get and the tty version returns fs_filetype: CharacterDevice while the piped version returns fs_filetype: Unknown meaning that the module may use this to act differently.

Would you be able to share the source code of this module? The bug may be in TinyGo's standard library, but it might also be in wasi-libc. This may also be a bug that's since been fixed in wasi-libc and may require a newer build than you might be using. Hard to tell! If you're able to share the original source we can try to help dig in further.

Furthermore you mention fwrite("test\n", 5, 1, stdout); reproduces this behavior for you. Locally however I do not see a reproduction with a simple program doing that. This may indicate that this was a bug in wasi-libc that's since been fixed. Could you share the full source of the program (perhaps the module too) with fwrite and the version of wasi-sdk that you're using?

[aykevl]

That being said though I'm not certian that this is a bug in Wasmtime.

Yeah, since reporting this bug I started to realize it's more likely to be a bug in wasm-libc.

The main difference here is that the module calls fd_fdstat_get and the tty version returns fs_filetype: CharacterDevice while the piped version returns fs_filetype: Unknown meaning that the module may use this to act differently.

Thanks! I wasn't aware that WASI allowed inspecting the output file type.

Would you be able to share the source code of this module?

It's essentially just testdata/cgo in https://github.com/tinygo-org/tinygo/pull/4101/files but without the fflush workaround.
Unfortunately, when I tried to reproduce it today I couldn't get it to fail. I don't remember updating anything (like wasmtime) so not sure why this is the case. Closing, I'll reopen the issue once I manage to reproduce it again.

[aykevl]

Nevermind, that was a silly mistake on my side.

I can reproduce it using the following steps (this assumes you already have a working TinyGo build):

1. Check out the cgo-printf branch of TinyGo.
2. run go install, tinygo clean
3. Comment out the fflush call at the bottom of testdata/cgo/main.c. (You can also uncomment most of the main function in testdata/cgo/main.go if you'd like).
4. Build a binary using tinygo build -o test.wasm -target=wasi ./testdata/cgo
5. Run it using wasmtime run test.wasm | tail.

That's rather involved just to reproduce this issue, I can try to make a reproducer that doesn't use TinyGo.

[aykevl]

This may also be a bug that's since been fixed in wasi-libc and may require a newer build than you might be using.

Tried again with the main branch of wasi-libc, same issue. So whatever it is, it doesn't look like it's fixed there.

[aykevl]

Update: I can't seem to reproduce this with a simple 'hello world' in C, this needs a bit more investigation.

[aykevl]

Ok, figured it out. I need to call __wasm_call_dtors before exiting. Apparently it flushes the stdout buffer.

See:
https://github.com/WebAssembly/wasi-libc/blob/main/libc-bottom-half/crt/crt1-command.c#L46