Returned errnos are no longer printed on trace log level

[marmistrz]

After updating wasmtime to latest master, I'm no longer getting the errno trace level messages.
I'm running the following code compiled to wasm32-wasi using Rust 1.42.0:

use rustyline::error::ReadlineError;
use rustyline::Editor;

fn main() {
    // `()` can be used when no completer is required
    let mut rl = Editor::<()>::new();
    loop {
        let readline = rl.readline(">> ");
        match readline {
            Ok(line) => {
                rl.add_history_entry(line.as_str());
                println!("Line: {}", line);
            },
            Err(ReadlineError::Interrupted) => {
                println!("CTRL-C");
                break
            },
            Err(ReadlineError::Eof) => {
                println!("CTRL-D");
                break
            },
            Err(err) => {
                println!("Error: {:?}", err);
                break
            }
        }
    }
}

My command line is:

RUST_LOG=wasi_common=trace cargo run --release -- run --env RUST_LOG=trace /path/to/rl.wasm

On 32595fa:

 DEBUG wasi_common::ctx > WasiCtx inserting entry PendingEntry::Thunk(0x7ffeb84de258)
 DEBUG wasi_common::sys::unix::entry > Host fd 0 is a char device
 DEBUG wasi_common::ctx              > WasiCtx inserted at Fd(0)
 DEBUG wasi_common::ctx              > WasiCtx inserting entry PendingEntry::Thunk(0x7ffeb84de258)
 DEBUG wasi_common::sys::unix::entry > Host fd 1 is a char device
 DEBUG wasi_common::ctx              > WasiCtx inserted at Fd(1)
 DEBUG wasi_common::ctx              > WasiCtx inserting entry PendingEntry::Thunk(0x7ffeb84de258)
 DEBUG wasi_common::sys::unix::entry > Host fd 2 is a char device
 DEBUG wasi_common::ctx              > WasiCtx inserted at Fd(2)
 DEBUG wasi_common::old::snapshot_0::ctx > WasiCtx inserting (0, Some(PendingEntry::Thunk(0x7ffeb84de780)))
 DEBUG wasi_common::old::snapshot_0::sys::unix::entry_impl > Host fd 0 is a char device
 DEBUG wasi_common::old::snapshot_0::ctx                   > WasiCtx inserting (1, Some(PendingEntry::Thunk(0x7ffeb84de790)))
 DEBUG wasi_common::old::snapshot_0::sys::unix::entry_impl > Host fd 1 is a char device
 DEBUG wasi_common::old::snapshot_0::ctx                   > WasiCtx inserting (2, Some(PendingEntry::Thunk(0x7ffeb84de7a0)))
 DEBUG wasi_common::old::snapshot_0::sys::unix::entry_impl > Host fd 2 is a char device
 TRACE wasi_common::snapshots::wasi_snapshot_preview1      > environ_sizes_get
 TRACE wasi_common::snapshots::wasi_snapshot_preview1      >      | *environ_count_ptr=1
 TRACE wasi_common::snapshots::wasi_snapshot_preview1      >      | *environ_size_ptr=15
 TRACE wasi_common::snapshots::wasi_snapshot_preview1      > environ_get(environ=*guest 0x120030, environ_buf=*guest 0x120010)
 TRACE wasi_common::snapshots::wasi_snapshot_preview1      > fd_prestat_get(fd=Fd(3))
 TRACE wasi_common::snapshots::wasi_snapshot_preview1      > random_get(buf=*guest 0xffe48, buf_len=16)
 TRACE wasi_common::snapshots::wasi_snapshot_preview1      > fd_write(fd=Fd(1), ciovs=*guest 0xffe08/1)

 TRACE wasi_common::snapshots::wasi_snapshot_preview1      >      | *nwritten=1
 TRACE wasi_common::snapshots::wasi_snapshot_preview1      > fd_write(fd=Fd(1), ciovs=*guest 0xffe08/1)
CTRL-D
 TRACE wasi_common::snapshots::wasi_snapshot_preview1      >      | *nwritten=7

On f700efe:

 DEBUG wasi_common::ctx > WasiCtx inserting (2, PendingFdEntry::Thunk(0x7ffd3f66bab8))
 DEBUG wasi_common::sys::unix::fdentry_impl > Host fd 2 is a char device
 DEBUG wasi_common::ctx                     > WasiCtx inserting (1, PendingFdEntry::Thunk(0x7ffd3f66bab8))
 DEBUG wasi_common::sys::unix::fdentry_impl > Host fd 1 is a char device
 DEBUG wasi_common::ctx                     > WasiCtx inserting (0, PendingFdEntry::Thunk(0x7ffd3f66bab8))
 DEBUG wasi_common::sys::unix::fdentry_impl > Host fd 0 is a char device
 DEBUG wasi_common::old::snapshot_0::ctx    > WasiCtx inserting (2, PendingFdEntry::Thunk(0x7ffd3f66bac8))
 DEBUG wasi_common::old::snapshot_0::sys::unix::fdentry_impl > Host fd 2 is a char device
 DEBUG wasi_common::old::snapshot_0::ctx                     > WasiCtx inserting (1, PendingFdEntry::Thunk(0x7ffd3f66bac8))
 DEBUG wasi_common::old::snapshot_0::sys::unix::fdentry_impl > Host fd 1 is a char device
 DEBUG wasi_common::old::snapshot_0::ctx                     > WasiCtx inserting (0, PendingFdEntry::Thunk(0x7ffd3f66bac8))
 DEBUG wasi_common::old::snapshot_0::sys::unix::fdentry_impl > Host fd 0 is a char device
 TRACE wasi_common::hostcalls_impl::misc                     > environ_sizes_get(environ_count_ptr=0xffffc, environ_size_ptr=0xffff8)
 TRACE wasi_common::hostcalls_impl::misc                     >      | *environ_count_ptr=1
 TRACE wasi_common::hostcalls_impl::misc                     >      | *environ_size_ptr=15
 TRACE wasi_common::hostcalls                                >      | errno=ESUCCESS (No error occurred. System call completed successfully.)
 TRACE wasi_common::hostcalls_impl::misc                     > environ_get(environ_ptr=0x120030, environ_buf=0x120010)
 TRACE wasi_common::hostcalls                                >      | errno=ESUCCESS (No error occurred. System call completed successfully.)
 TRACE wasi_common::hostcalls_impl::fs                       > fd_prestat_get(fd=3, prestat_ptr=0xffff8)
 TRACE wasi_common::hostcalls                                >      | errno=EBADF (Bad file descriptor.)
 TRACE wasi_common::hostcalls_impl::misc                     > random_get(buf_ptr=0xffe48, buf_len=16)
 TRACE wasi_common::hostcalls                                >      | errno=ESUCCESS (No error occurred. System call completed successfully.)
 TRACE wasi_common::hostcalls_impl::fs                       > fd_write(fd=1, iovs_ptr=0xffe08, iovs_len=1, nwritten=0xffdfc)

 TRACE wasi_common::hostcalls_impl::fs                       >      | *nwritten=1
 TRACE wasi_common::hostcalls                                >      | errno=ESUCCESS (No error occurred. System call completed successfully.)
 TRACE wasi_common::hostcalls_impl::fs                       > fd_write(fd=1, iovs_ptr=0xffe08, iovs_len=1, nwritten=0xffdfc)
CTRL-D
 TRACE wasi_common::hostcalls_impl::fs                       >      | *nwritten=7
 TRACE wasi_common::hostcalls                                >      | errno=ESUCCESS (No error occurred. System call completed successfully.)

In other words, it's a regression introduced in #1202. cc @kubkon

[kubkon]

Yep, that's true. It's a regression introduced on purpose until we work out how to deal with logging in the wiggle crate. Fastly has certain strict requirements in that respect and the current idea is to have logging behind a feature flag in wiggle crate so that if the lib's consumer doesn't want to use/pull log, they won't have to.

[marmistrz]

Why aren't the log calls executed if they are present in the wig sources?

wasmtime/crates/wasi-common/wig/src/hostcalls.rs

Line 96 in 9d40e10

log::trace!(" | errno={}", ret);

[kubkon]

That’s because wig generates the shims for the old snapshot only, whereas wiggle is used in the currently used snapshot. We still temporarily use wig for autogenerating some of the glue for wasmtime, however, it’s restricted to things like memory export and the Wasi struct.