Stream: git-wasmtime

Topic: wasmtime / issue #7833 Output is different when connected...

view this post on Zulip Wasmtime GitHub notifications bot (Jan 27 2024 at 14:27):

aykevl added the bug label to Issue #7833.

view this post on Zulip Wasmtime GitHub notifications bot (Jan 27 2024 at 14:27):

aykevl opened issue #7833:

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.

view this post on Zulip Wasmtime GitHub notifications bot (Jan 27 2024 at 15:21):

aykevl edited issue #7833:

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);.

view this post on Zulip Wasmtime GitHub notifications bot (Jan 27 2024 at 21:15):

alexcrichton commented on issue #7833:

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?

view this post on Zulip Wasmtime GitHub notifications bot (Feb 15 2024 at 18:55):

aykevl closed issue #7833:

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);.

view this post on Zulip Wasmtime GitHub notifications bot (Feb 15 2024 at 18:55):

aykevl commented on issue #7833:

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.

view this post on Zulip Wasmtime GitHub notifications bot (Feb 15 2024 at 19:04):

aykevl commented on issue #7833:

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.

view this post on Zulip Wasmtime GitHub notifications bot (Feb 15 2024 at 19:04):

aykevl reopened issue #7833:

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);.

view this post on Zulip Wasmtime GitHub notifications bot (Feb 15 2024 at 19:06):

aykevl commented on issue #7833:

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.

view this post on Zulip Wasmtime GitHub notifications bot (Feb 15 2024 at 19:18):

aykevl commented on issue #7833:

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

view this post on Zulip Wasmtime GitHub notifications bot (Feb 15 2024 at 19:18):

aykevl edited a comment on issue #7833:

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

view this post on Zulip Wasmtime GitHub notifications bot (Feb 15 2024 at 19:29):

aykevl closed issue #7833:

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);.

view this post on Zulip Wasmtime GitHub notifications bot (Feb 15 2024 at 19:29):

aykevl commented on issue #7833:

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

Last updated: Nov 22 2024 at 17:03 UTC