wasmtime should have more options for debugging errors in early program startup

[bacongobbler]

given an example that displays output on stdout - like a "hello world" application - wasmtime --env appears to drop stdout entirely.

><> cat src/main.rs 
fn main() {
    println!("hello world!");
}
><> cargo build --target wasm32-wasi
    Finished dev [unoptimized + debuginfo] target(s) in 0.00s
><> wasmtime ./target/wasm32-wasi/debug/wasm32-wasi-demo.wasm 
hello world!
><> wasmtime --env 'FOO=bar' ./target/wasm32-wasi/debug/wasm32-wasi-demo.wasm 
><>

Tested with both 0.8.0 and the development release available on the releases page. Both demonstrate the same issue.

[bacongobbler]

My coworkers cannot appear to reproduce the issue. I will assume that this happens to be something on my end, and will continue investigating as I find time.

[peterhuene]

I'm also unable to reproduce this with current out of master.

What's the environment you're reproducing this in?

[bacongobbler]

Hi @peterhuene!

Here's what I know so far:

><> wasmtime --version
wasmtime 0.7.0
><> uname -a
Linux ultralisk 5.0.0-37-generic #40~18.04.1-Ubuntu SMP Thu Nov 14 12:06:39 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

This was with a fresh linux .tar.xz build from the dev release channel.

My terminal is plain ol' /bin/bash, using the Terminal app on Ubuntu.

Running with RUST_LOG=debug wasmtime ... and reviewing the thread dumps shows no difference in output between wasmtime and wasmtime --env.

After much debugging, I'm assuming there's something on my end interfering with the terminal output. Trying to isolate the issue in a linux container to reproduce the issue.

[bacongobbler]

Yep. Couldn't reproduce the issue from within a linux container. Closing as there's nothing actionable here on wasmtime's end. I'll update the ticket if I find anything more concrete for others. Thanks for reaching out!

[rene-fonseca]

Is it actually running anything? You can put in a infinite loop to see if it completes.

You can also check if stderr has same issue - and print in infinite loop to see if there is a flush issue.

[bacongobbler]

Good call @rene-fonseca. I just checked with another sample that runs in an infinite loop. The program exits immediately, so it appears that nothing is being executed.

use std::{thread, time};

fn main() {
    let duration = time::Duration::from_secs(3);

    println!("Hello!");

    loop {
        thread::sleep(duration);
        println!("Hello again!");
    }
}

Output:

><> wasmtime target/wasm32-wasi/debug/helloworld-demo.wasm 
Hello!
Hello again!
^C
><> wasmtime --env 'FOO=bar' target/wasm32-wasi/debug/helloworld-demo.wasm 
><>

[peterhuene]

What's the exit status? Perhaps it's signaling? Can you run it under gdb/lldb?

[bacongobbler]

exit code 71.

><> wasmtime --env 'FOO=bar' target/wasm32-wasi/debug/helloworld-demo.wasm 
><> echo $?
71

a document on linux system errors indicates this would be a protocol error: EPROTO.

[bacongobbler]

From /usr/include/sysexits.h, this actually resolves as an OSERR. I'll see what I can find under gdb/lldb but it does look like a localized issue.

#define EX_OSERR        71      /* system error (e.g., can't fork) */

[sunfishcode]

In this case it's a process exit status, so it's not an errno value. 71 is sometimes EX_OSERR.

It might be wasm's startup code, which uses EX_OSERR in the init code to report unlikely failures like __wasi_environ_get etc. failing, or malloc failing before main. It's possible that if your environment doesn't have much memory, the first call to memory.grow prompted by the first malloc call could fail. If so, updating to a new wasi-libc may help, as we avoid calling memory.grow until we actually need it.

Beyond that, we should consider giving wasmtime verbose messages, which could be used to indicate things like "I just failed a memory.grow call", so make it easier to debug these kinds of problems.