Improvements to the tracing and logging in wasmer

- Now using the fmt subscriber for improved formatting
- Using spans on all syscalls
- Added recorded fields on the spans instead trace and debug macros
- Adding timing on all syscall

Cargo.lock

@@ -4890,6 +4890,8 @@ dependencies = [
  "time 0.3.20",
  "tldextract",
  "toml",
+ "tracing",
+ "tracing-subscriber 0.3.16",
  "unix_mode",
  "url",
  "walkdir",

lib/api/src/function_env.rs

@@ -1,4 +1,4 @@
-use std::{any::Any, marker::PhantomData};
+use std::{any::Any, fmt::Debug, marker::PhantomData};
 
 use crate::vm::VMFunctionEnvironment;
 
@@ -102,6 +102,12 @@ pub struct FunctionEnvMut<'a, T: 'a> {
     pub(crate) func_env: FunctionEnv<T>,
 }
 
+impl<'a, T> Debug for FunctionEnvMut<'a, T> {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        write!(f, "env_mut")
+    }
+}
+
 impl<T: Send + 'static> FunctionEnvMut<'_, T> {
     /// Returns a reference to the host state in this function environement.
     pub fn data(&self) -> &T {

lib/api/src/ptr.rs

@@ -278,11 +278,6 @@ impl<T: ValueType, M: MemorySize> Eq for WasmPtr<T, M> {}
 
 impl<T: ValueType, M: MemorySize> fmt::Debug for WasmPtr<T, M> {
     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
-        write!(
+        write!(f, "{}(@{})", std::any::type_name::<T>(), self.offset.into())
-            f,
-            "WasmPtr(offset: {}, pointer: {:#x})",
-            self.offset.into(),
-            self.offset.into()
-        )
     }
 }

lib/cli/Cargo.toml

@@ -91,6 +91,8 @@ pathdiff = "0.2.1"
 sha2 = "0.10.6"
 object = "0.30.0"
 wasm-coredump-builder = { version = "0.1.11" }
+tracing = { version = "0.1", optional = true }
+tracing-subscriber = { version = "0.3", features = [ "env-filter", "fmt" ], optional = true }
 
 [build-dependencies]
 chrono = { version = "^0.4", default-features = false, features = [ "std", "clock" ] }
@@ -111,6 +113,7 @@ default = [
     "wasmer-artifact-create",
     "static-artifact-create",
     "webc_runner",
+    "tracing"
 ]
 cache = ["wasmer-cache"]
 cache-blake3-pure = ["wasmer-cache/blake3-pure"]
@@ -167,6 +170,7 @@ debug = ["fern", "wasmer-wasi/logging"]
 disable-all-logging = ["wasmer-wasi/disable-all-logging", "log/release_max_level_off"]
 headless = []
 headless-minimal = ["headless", "disable-all-logging", "wasi"]
+tracing = [ "dep:tracing", "tracing-subscriber" ]
 
 # Optional
 enable-serde = [

lib/cli/src/logging.rs

@@ -1,4 +1,36 @@
 //! Logging functions for the debug feature.
+
+/// Subroutine to instantiate the loggers
+#[cfg(feature = "tracing")]
+pub fn set_up_logging(verbose: u8) -> Result<(), String> {
+    use tracing_subscriber::prelude::*;
+    use tracing_subscriber::{fmt, EnvFilter};
+
+    let fmt_layer = fmt::layer()
+        .with_target(false)
+        .with_span_events(fmt::format::FmtSpan::CLOSE)
+        .with_thread_ids(true)
+        .compact();
+
+    let filter_layer = EnvFilter::try_from_default_env()
+        .or_else(|_| match verbose {
+            1 => EnvFilter::try_new("debug"),
+            _ => EnvFilter::try_new("trace"),
+        })
+        .unwrap();
+
+    tracing_subscriber::registry()
+        .with(filter_layer)
+        .with(fmt_layer)
+        .init();
+
+    Ok(())
+}
+
+/// Subroutine to instantiate the loggers
+#[deprecated("please use the tracing feature instead")]
+#[cfg(not(feature = "tracing"))]
+pub fn set_up_logging(verbose: u8) -> Result<(), String> {
     use crate::utils::wasmer_should_print_color;
     use anyhow::Result;
     use fern::colors::{Color, ColoredLevelConfig};
@@ -7,8 +39,6 @@ use std::time;
     /// The debug level
     pub type DebugLevel = log::LevelFilter;
 
-/// Subroutine to instantiate the loggers
-pub fn set_up_logging(verbose: u8) -> Result<(), String> {
     let colors_line = ColoredLevelConfig::new()
         .error(Color::Red)
         .warn(Color::Yellow)

lib/wasi-types/src/wasi/bindings.rs

@@ -417,11 +417,7 @@ impl Errno {
 }
 impl core::fmt::Debug for Errno {
     fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result {
-        f.debug_struct("Errno")
+        write!(f, "Errno::{}", &self.name())
-            .field("code", &(*self as i32))
-            .field("name", &self.name())
-            .field("message", &self.message())
-            .finish()
     }
 }
 impl core::fmt::Display for Errno {
@@ -528,11 +524,7 @@ impl BusErrno {
 }
 impl core::fmt::Debug for BusErrno {
     fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result {
-        f.debug_struct("BusErrno")
+        write!(f, "BusErrno::{}", &self.name())
-            .field("code", &(*self as i32))
-            .field("name", &self.name())
-            .field("message", &self.message())
-            .finish()
     }
 }
 impl core::fmt::Display for BusErrno {
@@ -2166,6 +2158,14 @@ impl core::fmt::Debug for Bool {
         }
     }
 }
+impl core::fmt::Display for Bool {
+    fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result {
+        match self {
+            Bool::False => write!(f, "false"),
+            Bool::True => write!(f, "true"),
+        }
+    }
+}
 #[repr(C)]
 #[derive(Copy, Clone)]
 pub struct OptionTimestamp {

lib/wasi/Cargo.toml

@@ -13,7 +13,7 @@ edition = "2018"
 [dependencies]
 cfg-if = "1.0"
 thiserror = "1"
-tracing = "0.1"
+tracing = { version = "0.1" }
 getrandom = "0.2"
 wasmer-wasi-types = { path = "../wasi-types", version = "=3.2.0-alpha.1" }
 wasmer-types = { path = "../types", version = "=3.2.0-alpha.1", default-features = false }

lib/wasi/src/os/task/process.rs

@@ -28,7 +28,7 @@ use super::{
 };
 
 /// Represents the ID of a sub-process
-#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
+#[derive(Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
 pub struct WasiProcessId(u32);
 
 impl WasiProcessId {
@@ -67,6 +67,12 @@ impl std::fmt::Display for WasiProcessId {
     }
 }
 
+impl std::fmt::Debug for WasiProcessId {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        write!(f, "{}", self.0)
+    }
+}
+
 /// Represents a process running within the compute state
 // TODO: fields should be private and only accessed via methods.
 #[derive(Debug, Clone)]

lib/wasi/src/os/task/thread.rs

@@ -22,7 +22,7 @@ use super::{
 };
 
 /// Represents the ID of a WASI thread
-#[derive(Debug, Default, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
+#[derive(Default, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
 pub struct WasiThreadId(u32);
 
 impl WasiThreadId {
@@ -67,6 +67,12 @@ impl std::fmt::Display for WasiThreadId {
     }
 }
 
+impl std::fmt::Debug for WasiThreadId {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        write!(f, "{}", self.0)
+    }
+}
+
 /// Represents a linked list of stack snapshots
 #[derive(Debug, Clone)]
 struct ThreadSnapshot {

lib/wasi/src/syscalls/legacy/snapshot0.rs

@@ -1,3 +1,4 @@
+use tracing::{field, instrument, trace_span};
 use wasmer::{AsStoreMut, FunctionEnvMut, WasmPtr};
 use wasmer_wasi_types::wasi::{
     Errno, Event, EventFdReadwrite, Eventrwflags, Eventtype, Fd, Filesize, Filestat, Filetype,
@@ -20,6 +21,7 @@ use crate::{
 /// WARNING: this function involves saving, clobbering, and restoring unrelated
 /// Wasm memory.  If the memory clobbered by the current syscall is also used by
 /// that syscall, then it may break.
+#[instrument(level = "debug", skip_all, ret)]
 pub fn fd_filestat_get(
     mut ctx: FunctionEnvMut<WasiEnv>,
     fd: Fd,
@@ -72,6 +74,7 @@ pub fn fd_filestat_get(
 
 /// Wrapper around `syscalls::path_filestat_get` with extra logic to handle the size
 /// difference of `wasi_filestat_t`
+#[instrument(level = "debug", skip_all, ret)]
 pub fn path_filestat_get(
     mut ctx: FunctionEnvMut<WasiEnv>,
     fd: Fd,
@@ -115,6 +118,7 @@ pub fn path_filestat_get(
 
 /// Wrapper around `syscalls::fd_seek` with extra logic to remap the values
 /// of `Whence`
+#[instrument(level = "debug", skip_all, ret)]
 pub fn fd_seek(
     ctx: FunctionEnvMut<WasiEnv>,
     fd: Fd,
@@ -132,6 +136,7 @@ pub fn fd_seek(
 
 /// Wrapper around `syscalls::poll_oneoff` with extra logic to add the removed
 /// userdata field back
+#[instrument(level = "trace", skip_all, fields(timeout_ns = field::Empty, fd_guards = field::Empty, seen = field::Empty), ret, err)]
 pub fn poll_oneoff(
     mut ctx: FunctionEnvMut<WasiEnv>,
     in_: WasmPtr<Snapshot0Subscription, Memory32>,
@@ -157,12 +162,7 @@ pub fn poll_oneoff(
     let triggered_events = match triggered_events {
         Ok(a) => a,
         Err(err) => {
-            tracing::trace!(
+            tracing::trace!(err = err as u16);
-                "wasi[{}:{}]::poll_oneoff0 errno={}",
-                ctx.data().pid(),
-                ctx.data().tid(),
-                err
-            );
             return Ok(err);
         }
     };

lib/wasi/src/syscalls/mod.rs

@@ -21,6 +21,7 @@ pub mod wasix;
 
 use bytes::{Buf, BufMut};
 use futures::Future;
+use tracing::instrument;
 pub use wasi::*;
 pub use wasix::*;
 
@@ -664,7 +665,6 @@ pub(crate) fn write_buffer_array<M: MemorySize>(
 
     let mut current_buffer_offset = 0usize;
     for ((i, sub_buffer), ptr) in from.iter().enumerate().zip(ptrs.iter()) {
-        trace!("ptr: {:?}, subbuffer: {:?}", ptr, sub_buffer);
         let mut buf_offset = buffer.offset();
         buf_offset += wasi_try!(to_offset::<M>(current_buffer_offset));
         let new_ptr = WasmPtr::new(buf_offset);
@@ -935,6 +935,7 @@ where
     Ok(Errno::Success)
 }
 
+#[instrument(level = "debug", skip_all, fields(memory_stack_len = memory_stack.len(), rewind_stack_len = rewind_stack.len(), store_data_len = store_data.len()))]
 #[must_use = "the action must be passed to the call loop"]
 pub(crate) fn rewind<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
@@ -942,15 +943,6 @@ pub(crate) fn rewind<M: MemorySize>(
     rewind_stack: Bytes,
     store_data: Bytes,
 ) -> Errno {
-    trace!(
-        "wasi[{}:{}]::rewinding (memory_stack_size={}, rewind_size={}, store_data={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        memory_stack.len(),
-        rewind_stack.len(),
-        store_data.len()
-    );
-
     // Store the memory stack so that it can be restored later
     super::REWIND.with(|cell| cell.replace(Some(memory_stack)));
 

lib/wasi/src/syscalls/wasi/args_get.rs

@@ -10,12 +10,12 @@ use crate::syscalls::*;
 /// - `char *argv_buf`
 ///     A pointer to a buffer to write the argument string data.
 ///
+#[instrument(level = "debug", skip_all, ret)]
 pub fn args_get<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     argv: WasmPtr<WasmPtr<u8, M>, M>,
     argv_buf: WasmPtr<u8, M>,
 ) -> Errno {
-    debug!("wasi[{}:{}]::args_get", ctx.data().pid(), ctx.data().tid());
     let env = ctx.data();
     let (memory, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
 
@@ -27,7 +27,7 @@ pub fn args_get<M: MemorySize>(
     let result = write_buffer_array(&memory, &args, argv, argv_buf);
 
     debug!(
-        "=> args:\n{}",
+        "args:\n{}",
         state
             .args
             .iter()

lib/wasi/src/syscalls/wasi/args_sizes_get.rs

@@ -8,16 +8,12 @@ use crate::syscalls::*;
 ///     The number of arguments.
 /// - `size_t *argv_buf_size`
 ///     The size of the argument string data.
+#[instrument(level = "debug", skip_all, ret)]
 pub fn args_sizes_get<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     argc: WasmPtr<M::Offset, M>,
     argv_buf_size: WasmPtr<M::Offset, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::args_sizes_get",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (memory, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
 
@@ -31,7 +27,7 @@ pub fn args_sizes_get<M: MemorySize>(
     wasi_try_mem!(argc.write(argc_val));
     wasi_try_mem!(argv_buf_size.write(argv_buf_size_val));
 
-    debug!("=> argc={}, argv_buf_size={}", argc_val, argv_buf_size_val);
+    debug!("argc={}, argv_buf_size={}", argc_val, argv_buf_size_val);
 
     Errno::Success
 }

lib/wasi/src/syscalls/wasi/clock_res_get.rs

@@ -9,16 +9,12 @@ use crate::syscalls::*;
 /// Output:
 /// - `Timestamp *resolution`
 ///     The resolution of the clock in nanoseconds
+#[instrument(level = "trace", skip_all, ret)]
 pub fn clock_res_get<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     clock_id: Snapshot0Clockid,
     resolution: WasmPtr<Timestamp, M>,
 ) -> Errno {
-    trace!(
-        "wasi[{}:{}]::clock_res_get",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
 

lib/wasi/src/syscalls/wasi/clock_time_get.rs

@@ -11,18 +11,13 @@ use crate::syscalls::*;
 /// Output:
 /// - `Timestamp *time`
 ///     The value of the clock in nanoseconds
+#[instrument(level = "trace", skip_all, fields(clock_id, precision), ret)]
 pub fn clock_time_get<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     clock_id: Snapshot0Clockid,
     precision: Timestamp,
     time: WasmPtr<Timestamp, M>,
 ) -> Errno {
-    /*
-    debug!(
-        "wasi::clock_time_get clock_id: {}, precision: {}",
-        clock_id as u8, precision
-    );
-    */
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
 
@@ -34,13 +29,5 @@ pub fn clock_time_get<M: MemorySize>(
         }
     };
     wasi_try_mem!(time.write(&memory, t_out as Timestamp));
-
-    /*
-    trace!(
-        "time: {} => {}",
-        wasi_try_mem!(time.deref(&memory).read()),
-        result
-    );
-    */
     Errno::Success
 }

lib/wasi/src/syscalls/wasi/clock_time_set.rs

@@ -8,16 +8,12 @@ use crate::syscalls::*;
 ///     The ID of the clock to query
 /// - `Timestamp *time`
 ///     The value of the clock in nanoseconds
+#[instrument(level = "trace", skip_all, fields(clock_id, time), ret)]
 pub fn clock_time_set<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     clock_id: Snapshot0Clockid,
     time: Timestamp,
 ) -> Errno {
-    trace!(
-        "wasi::clock_time_set clock_id: {:?}, time: {}",
-        clock_id,
-        time
-    );
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
 
@@ -30,6 +26,5 @@ pub fn clock_time_set<M: MemorySize>(
 
     let mut guard = env.state.clock_offset.lock().unwrap();
     guard.insert(clock_id, t_offset);
-
     Errno::Success
 }

lib/wasi/src/syscalls/wasi/environ_get.rs

@@ -9,18 +9,14 @@ use crate::syscalls::*;
 ///     A pointer to a buffer to write the environment variable pointers.
 /// - `char *environ_buf`
 ///     A pointer to a buffer to write the environment variable string data.
+#[instrument(level = "debug", skip_all, ret)]
 pub fn environ_get<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     environ: WasmPtr<WasmPtr<u8, M>, M>,
     environ_buf: WasmPtr<u8, M>,
 ) -> Errno {
-    debug!(
-        "wasi::environ_get. Environ: {:?}, environ_buf: {:?}",
-        environ, environ_buf
-    );
     let env = ctx.data();
     let (memory, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
-    trace!(" -> State envs: {:?}", state.envs);
 
     write_buffer_array(&memory, &*state.envs, environ, environ_buf)
 }

lib/wasi/src/syscalls/wasi/environ_sizes_get.rs

@@ -8,16 +8,12 @@ use crate::syscalls::*;
 ///     The number of environment variables.
 /// - `size_t *environ_buf_size`
 ///     The size of the environment variable string data.
+#[instrument(level = "trace", skip_all, ret)]
 pub fn environ_sizes_get<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     environ_count: WasmPtr<M::Offset, M>,
     environ_buf_size: WasmPtr<M::Offset, M>,
 ) -> Errno {
-    trace!(
-        "wasi[{}:{}]::environ_sizes_get",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (memory, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
 
@@ -32,9 +28,8 @@ pub fn environ_sizes_get<M: MemorySize>(
     wasi_try_mem!(environ_buf_size.write(env_buf_size));
 
     trace!(
-        "env_var_count: {}, env_buf_size: {}",
+        %env_var_count,
-        env_var_count,
+        %env_buf_size
-        env_buf_size
     );
 
     Errno::Success

lib/wasi/src/syscalls/wasi/fd_advise.rs

@@ -12,6 +12,7 @@ use crate::syscalls::*;
 ///     The length from the offset to which the advice applies
 /// - `__wasi_advice_t advice`
 ///     The advice to give
+#[instrument(level = "debug", skip_all, fields(fd, offset, len, advice), ret)]
 pub fn fd_advise(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -19,13 +20,6 @@ pub fn fd_advise(
     len: Filesize,
     advice: Advice,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::fd_advise: fd={}",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd
-    );
-
     // this is used for our own benefit, so just returning success is a valid
     // implementation for now
     Errno::Success

lib/wasi/src/syscalls/wasi/fd_allocate.rs

@@ -10,17 +10,13 @@ use crate::syscalls::*;
 ///     The offset from the start marking the beginning of the allocation
 /// - `Filesize len`
 ///     The length from the offset marking the end of the allocation
+#[instrument(level = "debug", skip_all, fields(fd, offset, len), ret)]
 pub fn fd_allocate(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
     offset: Filesize,
     len: Filesize,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::fd_allocate",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (_, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
     let fd_entry = wasi_try!(state.fs.get_fd(fd));
@@ -52,7 +48,7 @@ pub fn fd_allocate(
         }
     }
     inode.stat.write().unwrap().st_size = new_size;
-    debug!("New file size: {}", new_size);
+    debug!(%new_size);
 
     Errno::Success
 }

lib/wasi/src/syscalls/wasi/fd_close.rs

@@ -12,14 +12,8 @@ use crate::syscalls::*;
 ///     If `fd` is a directory
 /// - `Errno::Badf`
 ///     If `fd` is invalid or not open
+#[instrument(level = "debug", skip_all, fields(fd), ret, err)]
 pub fn fd_close(mut ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::fd_close: fd={}",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd
-    );
-
     let env = ctx.data();
     let (_, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
     wasi_try_ok!(state.fs.close_fd(fd));

lib/wasi/src/syscalls/wasi/fd_datasync.rs

@@ -6,12 +6,8 @@ use crate::syscalls::*;
 /// Inputs:
 /// - `Fd fd`
 ///     The file descriptor to sync
+#[instrument(level = "debug", skip_all, fields(fd), ret, err)]
 pub fn fd_datasync(mut ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::fd_datasync",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let state = env.state.clone();
     let fd_entry = wasi_try_ok!(state.fs.get_fd(fd));

lib/wasi/src/syscalls/wasi/fd_dup.rs

@@ -9,17 +9,17 @@ use crate::syscalls::*;
 /// Outputs:
 /// - `Fd fd`
 ///   The new file handle that is a duplicate of the original
+#[instrument(level = "debug", skip_all, fields(fd, ret_fd = field::Empty), ret)]
 pub fn fd_dup<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
     ret_fd: WasmPtr<WasiFd, M>,
 ) -> Errno {
-    debug!("wasi[{}:{}]::fd_dup", ctx.data().pid(), ctx.data().tid());
-
     let env = ctx.data();
     let (memory, state) = env.get_memory_and_wasi_state(&ctx, 0);
     let fd = wasi_try!(state.fs.clone_fd(fd));
 
+    Span::current().record("ret_fd", fd);
     wasi_try_mem!(ret_fd.write(&memory, fd));
 
     Errno::Success

lib/wasi/src/syscalls/wasi/fd_event.rs

@@ -3,14 +3,13 @@ use crate::{fs::NotificationInner, syscalls::*};
 
 /// ### `fd_event()`
 /// Creates a file handle for event notifications
+#[instrument(level = "debug", skip_all, fields(initial_val, ret_fd = field::Empty), ret)]
 pub fn fd_event<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     initial_val: u64,
     flags: EventFdFlags,
     ret_fd: WasmPtr<WasiFd, M>,
 ) -> Errno {
-    debug!("wasi[{}:{}]::fd_event", ctx.data().pid(), ctx.data().tid());
-
     let env = ctx.data();
     let (memory, state, mut inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
 
@@ -32,12 +31,7 @@ pub fn fd_event<M: MemorySize>(
         .fs
         .create_fd(rights, rights, Fdflags::empty(), 0, inode));
 
-    trace!(
+    Span::current().record("ret_fd", fd);
-        "wasi[{}:{}]::fd_event - event notifications created (fd={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd
-    );
     wasi_try_mem!(ret_fd.write(&memory, fd));
 
     Errno::Success

lib/wasi/src/syscalls/wasi/fd_fdstat_get.rs

@@ -9,18 +9,12 @@ use crate::syscalls::*;
 /// Output:
 /// - `Fdstat *buf`
 ///     The location where the metadata will be written
+#[instrument(level = "trace", skip_all, fields(fd), ret)]
 pub fn fd_fdstat_get<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
     buf_ptr: WasmPtr<Fdstat, M>,
 ) -> Errno {
-    trace!(
-        "wasi[{}:{}]::fd_fdstat_get: fd={}, buf_ptr={}",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd,
-        buf_ptr.offset()
-    );
     let env = ctx.data();
     let (memory, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
     let stat = wasi_try!(state.fs.fdstat(fd));

lib/wasi/src/syscalls/wasi/fd_fdstat_set_flags.rs

@@ -8,19 +8,12 @@ use crate::syscalls::*;
 ///     The file descriptor to apply the new flags to
 /// - `Fdflags flags`
 ///     The flags to apply to `fd`
+#[instrument(level = "debug", skip_all, fields(fd), ret, err)]
 pub fn fd_fdstat_set_flags(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
     flags: Fdflags,
 ) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::fd_fdstat_set_flags (fd={}, flags={:?})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd,
-        flags
-    );
-
     {
         let env = ctx.data();
         let (_, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
@@ -29,13 +22,6 @@ pub fn fd_fdstat_set_flags(
         let inode = fd_entry.inode.clone();
 
         if !fd_entry.rights.contains(Rights::FD_FDSTAT_SET_FLAGS) {
-            debug!(
-                "wasi[{}:{}]::fd_fdstat_set_flags (fd={}, flags={:?}) - access denied",
-                ctx.data().pid(),
-                ctx.data().tid(),
-                fd,
-                flags
-            );
             return Ok(Errno::Access);
         }
     }

lib/wasi/src/syscalls/wasi/fd_fdstat_set_rights.rs

@@ -10,17 +10,13 @@ use crate::syscalls::*;
 ///     The rights to apply to `fd`
 /// - `Rights fs_rights_inheriting`
 ///     The inheriting rights to apply to `fd`
+#[instrument(level = "debug", skip_all, fields(fd), ret)]
 pub fn fd_fdstat_set_rights(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
     fs_rights_base: Rights,
     fs_rights_inheriting: Rights,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::fd_fdstat_set_rights",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (_, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
     let mut fd_map = state.fs.fd_map.write().unwrap();

lib/wasi/src/syscalls/wasi/fd_filestat_get.rs

@@ -9,6 +9,7 @@ use crate::syscalls::*;
 /// Output:
 /// - `Filestat *buf`
 ///     Where the metadata from `fd` will be written
+#[instrument(level = "debug", skip_all, fields(fd), ret)]
 pub fn fd_filestat_get<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -30,11 +31,6 @@ pub(crate) fn fd_filestat_get_internal<M: MemorySize>(
     fd: WasiFd,
     buf: WasmPtr<Filestat, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::fd_filestat_get: fd={fd}",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (memory, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
     let fd_entry = wasi_try!(state.fs.get_fd(fd));

lib/wasi/src/syscalls/wasi/fd_filestat_set_size.rs

@@ -8,16 +8,12 @@ use crate::syscalls::*;
 ///     File descriptor to adjust
 /// - `Filesize st_size`
 ///     New size that `fd` will be set to
+#[instrument(level = "debug", skip_all, fields(fd, st_size), ret)]
 pub fn fd_filestat_set_size(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
     st_size: Filesize,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::fd_filestat_set_size",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (_, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
     let fd_entry = wasi_try!(state.fs.get_fd(fd));

lib/wasi/src/syscalls/wasi/fd_filestat_set_times.rs

@@ -10,6 +10,7 @@ use crate::syscalls::*;
 ///     Last modified time
 /// - `Fstflags fst_flags`
 ///     Bit-vector for controlling which times get set
+#[instrument(level = "debug", skip_all, fields(fd, st_atim, st_mtim), ret)]
 pub fn fd_filestat_set_times(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -17,11 +18,6 @@ pub fn fd_filestat_set_times(
     st_mtim: Timestamp,
     fst_flags: Fstflags,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::fd_filestat_set_times",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (_, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
     let fd_entry = wasi_try!(state.fs.get_fd(fd));

lib/wasi/src/syscalls/wasi/fd_prestat_dir_name.rs

@@ -1,22 +1,17 @@
 use super::*;
 use crate::syscalls::*;
 
+#[instrument(level = "trace", skip_all, fields(fd, path = field::Empty), ret)]
 pub fn fd_prestat_dir_name<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
     path: WasmPtr<u8, M>,
     path_len: M::Offset,
 ) -> Errno {
-    trace!(
-        "wasi[{}:{}]::fd_prestat_dir_name: fd={}, path_len={}",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd,
-        path_len
-    );
     let env = ctx.data();
     let (memory, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
     let path_chars = wasi_try_mem!(path.slice(&memory, path_len));
+    Span::current().record("path", get_input_str!(&memory, path, path_len).as_str());
 
     let inode = wasi_try!(state.fs.get_fd_inode(fd));
 

lib/wasi/src/syscalls/wasi/fd_prestat_get.rs

@@ -9,27 +9,17 @@ use crate::syscalls::*;
 /// Output:
 /// - `__wasi_prestat *buf`
 ///     Where the metadata will be written
+#[instrument(level = "trace", skip_all, fields(fd), ret)]
 pub fn fd_prestat_get<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
     buf: WasmPtr<Prestat, M>,
 ) -> Errno {
-    trace!(
-        "wasi[{}:{}]::fd_prestat_get: fd={}",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd
-    );
     let env = ctx.data();
     let (memory, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
 
     let prestat_ptr = buf.deref(&memory);
-    wasi_try_mem!(
+    wasi_try_mem!(prestat_ptr.write(wasi_try!(state.fs.prestat_fd(fd))));
-        prestat_ptr.write(wasi_try!(state.fs.prestat_fd(fd).map_err(|code| {
-            debug!("fd_prestat_get failed (fd={}) - errno={}", fd, code);
-            code
-        })))
-    );
 
     Errno::Success
 }

lib/wasi/src/syscalls/wasi/fd_read.rs

@@ -18,6 +18,7 @@ use crate::{fs::NotificationInner, syscalls::*};
 /// - `u32 *nread`
 ///     Number of bytes read
 ///
+#[instrument(level = "trace", skip_all, fields(fd, nread = field::Empty), ret, err)]
 pub fn fd_read<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -41,29 +42,13 @@ pub fn fd_read<M: MemorySize>(
 
     let mut ret = Errno::Success;
     let bytes_read = match res {
-        Ok(bytes_read) => {
+        Ok(bytes_read) => bytes_read,
-            trace!(
-                %fd,
-                %bytes_read,
-                "wasi[{}:{}]::fd_read",
-                ctx.data().pid(),
-                ctx.data().tid(),
-            );
-            bytes_read
-        }
         Err(err) => {
-            let read_err = err.name();
-            trace!(
-                %fd,
-                %read_err,
-                "wasi[{}:{}]::fd_read",
-                ctx.data().pid(),
-                ctx.data().tid(),
-            );
             ret = err;
             0
         }
     };
+    Span::current().record("nread", bytes_read);
 
     let bytes_read: M::Offset = wasi_try_ok!(bytes_read.try_into().map_err(|_| Errno::Overflow));
 
@@ -93,6 +78,7 @@ pub fn fd_read<M: MemorySize>(
 /// Output:
 /// - `size_t nread`
 ///     The number of bytes read
+#[instrument(level = "trace", skip_all, fields(fd, offset, nread), ret, err)]
 pub fn fd_pread<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -108,33 +94,13 @@ pub fn fd_pread<M: MemorySize>(
 
     let mut ret = Errno::Success;
     let bytes_read = match res {
-        Ok(bytes_read) => {
+        Ok(bytes_read) => bytes_read,
-            trace!(
-                %fd,
-                %offset,
-                %bytes_read,
-                "wasi[{}:{}]::fd_pread - {:?}",
-                ctx.data().pid(),
-                ctx.data().tid(),
-                ret
-            );
-            bytes_read
-        }
         Err(err) => {
-            let read_err = err.name();
-            trace!(
-                %fd,
-                %offset,
-                %read_err,
-                "wasi[{}:{}]::fd_pread - {:?}",
-                ctx.data().pid(),
-                ctx.data().tid(),
-                ret
-            );
             ret = err;
             0
         }
     };
+    Span::current().record("nread", bytes_read);
 
     let bytes_read: M::Offset = wasi_try_ok!(bytes_read.try_into().map_err(|_| Errno::Overflow));
 

lib/wasi/src/syscalls/wasi/fd_readdir.rs

@@ -16,6 +16,7 @@ use crate::syscalls::*;
 /// - `u32 *bufused`
 ///     The Number of bytes stored in `buf`; if less than `buf_len` then entire
 ///     directory has been read
+#[instrument(level = "trace", skip_all, fields(fd), ret)]
 pub fn fd_readdir<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -24,11 +25,6 @@ pub fn fd_readdir<M: MemorySize>(
     cookie: Dircookie,
     bufused: WasmPtr<M::Offset, M>,
 ) -> Errno {
-    trace!(
-        "wasi[{}:{}]::fd_readdir",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (memory, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
     // TODO: figure out how this is supposed to work;
@@ -44,7 +40,7 @@ pub fn fd_readdir<M: MemorySize>(
         let guard = working_dir.inode.read();
         match guard.deref() {
             Kind::Dir { path, entries, .. } => {
-                debug!("Reading dir {:?}", path);
+                trace!("reading dir {:?}", path);
                 // TODO: refactor this code
                 // we need to support multiple calls,
                 // simple and obviously correct implementation for now:
@@ -56,7 +52,7 @@ pub fn fd_readdir<M: MemorySize>(
                     .into_iter()
                     .map(|entry| {
                         let filename = entry.file_name().to_string_lossy().to_string();
-                        debug!("Getting file: {:?}", filename);
+                        trace!("getting file: {:?}", filename);
                         let filetype = virtual_file_type_to_wasi_file_type(
                             entry.file_type().map_err(fs_error_into_wasi_err)?,
                         );
@@ -79,7 +75,7 @@ pub fn fd_readdir<M: MemorySize>(
                 entry_vec
             }
             Kind::Root { entries } => {
-                debug!("Reading root");
+                trace!("reading root");
                 let sorted_entries = {
                     let mut entry_vec: Vec<(String, InodeGuard)> = entries
                         .iter()
@@ -108,7 +104,7 @@ pub fn fd_readdir<M: MemorySize>(
     for (entry_path_str, wasi_file_type, ino) in entries.iter().skip(cookie as usize) {
         cur_cookie += 1;
         let namlen = entry_path_str.len();
-        debug!("Returning dirent for {}", entry_path_str);
+        trace!("returning dirent for {}", entry_path_str);
         let dirent = Dirent {
             d_next: cur_cookie,
             d_ino: *ino,

lib/wasi/src/syscalls/wasi/fd_renumber.rs

@@ -8,14 +8,8 @@ use crate::syscalls::*;
 ///     File descriptor to copy
 /// - `Fd to`
 ///     Location to copy file descriptor to
+#[instrument(level = "debug", skip_all, fields(from, to), ret)]
 pub fn fd_renumber(ctx: FunctionEnvMut<'_, WasiEnv>, from: WasiFd, to: WasiFd) -> Errno {
-    debug!(
-        "wasi[{}:{}]::fd_renumber(from={}, to={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        from,
-        to
-    );
     if from == to {
         return Errno::Success;
     }

lib/wasi/src/syscalls/wasi/fd_seek.rs

@@ -13,6 +13,7 @@ use crate::syscalls::*;
 /// Output:
 /// - `Filesize *fd`
 ///     The new offset relative to the start of the file
+#[instrument(level = "trace", skip_all, fields(fd, offset, whence), ret)]
 pub fn fd_seek<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -20,15 +21,6 @@ pub fn fd_seek<M: MemorySize>(
     whence: Whence,
     newoffset: WasmPtr<Filesize, M>,
 ) -> Result<Errno, WasiError> {
-    trace!(
-        "wasi[{}:{}]::fd_seek: fd={}, offset={} from={:?}",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd,
-        offset,
-        whence,
-    );
-
     wasi_try_ok!(WasiEnv::process_signals_and_exit(&mut ctx)?);
 
     let env = ctx.data();
@@ -123,11 +115,7 @@ pub fn fd_seek<M: MemorySize>(
     wasi_try_mem_ok!(new_offset_ref.write(new_offset));
 
     trace!(
-        "wasi[{}:{}]::fd_seek: fd={}, new_offset={}",
+        %new_offset,
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd,
-        new_offset,
     );
 
     Ok(Errno::Success)

lib/wasi/src/syscalls/wasi/fd_sync.rs

@@ -10,9 +10,8 @@ use crate::syscalls::*;
 /// TODO: figure out which errors this should return
 /// - `Errno::Perm`
 /// - `Errno::Notcapable`
+#[instrument(level = "debug", skip_all, fields(fd), ret)]
 pub fn fd_sync(mut ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd) -> Result<Errno, WasiError> {
-    debug!("wasi[{}:{}]::fd_sync", ctx.data().pid(), ctx.data().tid());
-    debug!("=> fd={}", fd);
     let env = ctx.data();
     let (_, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
     let fd_entry = wasi_try_ok!(state.fs.get_fd(fd));

lib/wasi/src/syscalls/wasi/fd_tell.rs

@@ -9,13 +9,12 @@ use crate::syscalls::*;
 /// Output:
 /// - `Filesize *offset`
 ///     The offset of `fd` relative to the start of the file
+#[instrument(level = "debug", skip_all, fields(fd, offset = field::Empty), ret)]
 pub fn fd_tell<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
     offset: WasmPtr<Filesize, M>,
 ) -> Errno {
-    debug!("wasi::fd_tell");
-    debug!("wasi[{}:{}]::fd_tell", ctx.data().pid(), ctx.data().tid());
     let env = ctx.data();
     let (memory, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
     let offset_ref = offset.deref(&memory);
@@ -26,7 +25,9 @@ pub fn fd_tell<M: MemorySize>(
         return Errno::Access;
     }
 
-    wasi_try_mem!(offset_ref.write(fd_entry.offset.load(Ordering::Acquire)));
+    let offset = fd_entry.offset.load(Ordering::Acquire);
+    Span::current().record("offset", offset);
+    wasi_try_mem!(offset_ref.write(offset));
 
     Errno::Success
 }

lib/wasi/src/syscalls/wasi/fd_write.rs

@@ -15,6 +15,7 @@ use crate::syscalls::*;
 ///     Number of bytes written
 /// Errors:
 ///
+#[instrument(level = "trace", skip_all, fields(fd, nwritten = field::Empty), ret, err)]
 pub fn fd_write<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -22,13 +23,6 @@ pub fn fd_write<M: MemorySize>(
     iovs_len: M::Offset,
     nwritten: WasmPtr<M::Offset, M>,
 ) -> Result<Errno, WasiError> {
-    trace!(
-        "wasi[{}:{}]::fd_write: fd={}",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd,
-    );
-
     let offset = {
         let mut env = ctx.data();
         let state = env.state.clone();
@@ -55,6 +49,7 @@ pub fn fd_write<M: MemorySize>(
 /// Output:
 /// - `u32 *nwritten`
 ///     Number of bytes written
+#[instrument(level = "trace", skip_all, fields(fd, offset, nwritten = field::Empty), ret, err)]
 pub fn fd_pwrite<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -63,14 +58,6 @@ pub fn fd_pwrite<M: MemorySize>(
     offset: Filesize,
     nwritten: WasmPtr<M::Offset, M>,
 ) -> Result<Errno, WasiError> {
-    trace!(
-        "wasi[{}:{}]::fd_pwrite (fd={}, offset={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd,
-        offset,
-    );
-
     fd_write_internal::<M>(ctx, fd, iovs, iovs_len, offset as usize, nwritten, false)
 }
 
@@ -260,6 +247,7 @@ fn fd_write_internal<M: MemorySize>(
         }
         bytes_written
     };
+    Span::current().record("nwritten", bytes_written);
 
     let memory = env.memory_view(&ctx);
     let nwritten_ref = nwritten.deref(&memory);

lib/wasi/src/syscalls/wasi/mod.rs

@@ -83,3 +83,5 @@ pub use poll_oneoff::*;
 pub use proc_exit::*;
 pub use proc_raise::*;
 pub use random_get::*;
+
+use tracing::{debug_span, field, instrument, trace_span, Span};

lib/wasi/src/syscalls/wasi/path_create_directory.rs

@@ -14,17 +14,13 @@ use crate::syscalls::*;
 /// Required Rights:
 /// - Rights::PATH_CREATE_DIRECTORY
 ///     This right must be set on the directory that the file is created in (TODO: verify that this is true)
+#[instrument(level = "trace", skip_all, fields(fd, path = field::Empty), ret)]
 pub fn path_create_directory<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
     path: WasmPtr<u8, M>,
     path_len: M::Offset,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::path_create_directory",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (memory, state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
 
@@ -39,16 +35,13 @@ pub fn path_create_directory<M: MemorySize>(
         return Errno::Access;
     }
     let mut path_string = unsafe { get_input_str!(&memory, path, path_len) };
-    debug!("=> fd: {}, path: {}", fd, &path_string);
+    Span::current().record("path", path_string.as_str());
 
     // Convert relative paths into absolute paths
     if path_string.starts_with("./") {
         path_string = ctx.data().state.fs.relative_path_to_absolute(path_string);
         trace!(
-            "wasi[{}:{}]::rel_to_abs (name={}))",
+            %path_string
-            ctx.data().pid(),
-            ctx.data().tid(),
-            path_string
         );
     }
 
@@ -66,12 +59,8 @@ pub fn path_create_directory<M: MemorySize>(
         return Errno::Inval;
     }
 
-    debug!("Looking at components {:?}", &path_vec);
-
     let mut cur_dir_inode = working_dir.inode;
     for comp in &path_vec {
-        debug!("Creating dir {}", comp);
-
         let processing_cur_dir_inode = cur_dir_inode.clone();
         let mut guard = processing_cur_dir_inode.write();
         match guard.deref_mut() {

lib/wasi/src/syscalls/wasi/path_filestat_get.rs

@@ -15,6 +15,7 @@ use crate::syscalls::*;
 /// Output:
 /// - `__wasi_file_stat_t *buf`
 ///     The location where the metadata will be stored
+#[instrument(level = "trace", skip_all, fields(fd, path = field::Empty))]
 pub fn path_filestat_get<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -27,24 +28,12 @@ pub fn path_filestat_get<M: MemorySize>(
     let (memory, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
 
     let mut path_string = unsafe { get_input_str!(&memory, path, path_len) };
-    trace!(
-        "wasi[{}:{}]::path_filestat_get (fd={}, path={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd,
-        path_string
-    );
 
     // Convert relative paths into absolute paths
     if path_string.starts_with("./") {
         path_string = ctx.data().state.fs.relative_path_to_absolute(path_string);
-        trace!(
-            "wasi[{}:{}]::rel_to_abs (name={}))",
-            ctx.data().pid(),
-            ctx.data().tid(),
-            path_string
-        );
     }
+    Span::current().record("path", path_string.as_str());
 
     let stat = wasi_try!(path_filestat_get_internal(
         &memory,
@@ -87,8 +76,6 @@ pub(crate) fn path_filestat_get_internal(
     if !root_dir.rights.contains(Rights::PATH_FILESTAT_GET) {
         return Err(Errno::Access);
     }
-    debug!("=> base_fd: {}, path: {}", fd, path_string);
-
     let file_inode = state.fs.get_inode_at_path(
         inodes,
         fd,

lib/wasi/src/syscalls/wasi/path_filestat_set_times.rs

@@ -18,6 +18,7 @@ use crate::syscalls::*;
 ///     The timestamp that the last modified time attribute is set to
 /// - `Fstflags fst_flags`
 ///     A bitmask controlling which attributes are set
+#[instrument(level = "debug", skip_all, fields(fd, path = field::Empty, st_atim, st_mtim), ret)]
 pub fn path_filestat_set_times<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -28,11 +29,6 @@ pub fn path_filestat_set_times<M: MemorySize>(
     st_mtim: Timestamp,
     fst_flags: Fstflags,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::path_filestat_set_times",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (memory, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
     let fd_entry = wasi_try!(state.fs.get_fd(fd));
@@ -47,16 +43,13 @@ pub fn path_filestat_set_times<M: MemorySize>(
     }
 
     let mut path_string = unsafe { get_input_str!(&memory, path, path_len) };
-    debug!("=> base_fd: {}, path: {}", fd, &path_string);
+    Span::current().record("path", path_string.as_str());
 
     // Convert relative paths into absolute paths
     if path_string.starts_with("./") {
         path_string = ctx.data().state.fs.relative_path_to_absolute(path_string);
         trace!(
-            "wasi[{}:{}]::rel_to_abs (name={}))",
+            %path_string
-            ctx.data().pid(),
-            ctx.data().tid(),
-            path_string
         );
     }
 

lib/wasi/src/syscalls/wasi/path_link.rs

@@ -18,6 +18,7 @@ use crate::syscalls::*;
 ///     String containing the new file path
 /// - `u32 old_path_len`
 ///     Length of the `new_path` string
+#[instrument(level = "debug", skip_all, fields(old_fd, new_fd, old_path = field::Empty, new_path = field::Empty, follow_symlinks = false), ret)]
 pub fn path_link<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     old_fd: WasiFd,
@@ -28,20 +29,17 @@ pub fn path_link<M: MemorySize>(
     new_path: WasmPtr<u8, M>,
     new_path_len: M::Offset,
 ) -> Errno {
-    debug!("wasi[{}:{}]::path_link", ctx.data().pid(), ctx.data().tid());
     if old_flags & __WASI_LOOKUP_SYMLINK_FOLLOW != 0 {
-        debug!("  - will follow symlinks when opening path");
+        Span::current().record("follow_symlinks", true);
     }
     let env = ctx.data();
     let (memory, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
     let mut old_path_str = unsafe { get_input_str!(&memory, old_path, old_path_len) };
+    Span::current().record("old_path", old_path_str.as_str());
     let mut new_path_str = unsafe { get_input_str!(&memory, new_path, new_path_len) };
+    Span::current().record("new_path", new_path_str.as_str());
     let source_fd = wasi_try!(state.fs.get_fd(old_fd));
     let target_fd = wasi_try!(state.fs.get_fd(new_fd));
-    debug!(
-        "=> source_fd: {}, source_path: {}, target_fd: {}, target_path: {}",
-        old_fd, &old_path_str, new_fd, new_path_str
-    );
 
     if !source_fd.rights.contains(Rights::PATH_LINK_SOURCE)
         || !target_fd.rights.contains(Rights::PATH_LINK_TARGET)

lib/wasi/src/syscalls/wasi/path_open.rs

@@ -25,6 +25,7 @@ use crate::syscalls::*;
 ///     The new file descriptor
 /// Possible Errors:
 /// - `Errno::Access`, `Errno::Badf`, `Errno::Fault`, `Errno::Fbig?`, `Errno::Inval`, `Errno::Io`, `Errno::Loop`, `Errno::Mfile`, `Errno::Nametoolong?`, `Errno::Nfile`, `Errno::Noent`, `Errno::Notdir`, `Errno::Rofs`, and `Errno::Notcapable`
+#[instrument(level = "debug", skip_all, fields(dirfd, path = field::Empty, follow_symlinks = false, ret_fd = field::Empty), ret)]
 pub fn path_open<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     dirfd: WasiFd,
@@ -37,9 +38,8 @@ pub fn path_open<M: MemorySize>(
     fs_flags: Fdflags,
     fd: WasmPtr<WasiFd, M>,
 ) -> Errno {
-    debug!("wasi[{}:{}]::path_open", ctx.data().pid(), ctx.data().tid());
     if dirflags & __WASI_LOOKUP_SYMLINK_FOLLOW != 0 {
-        debug!("  - will follow symlinks when opening path");
+        Span::current().record("follow_symlinks", true);
     }
     let env = ctx.data();
     let (memory, mut state, mut inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
@@ -66,18 +66,15 @@ pub fn path_open<M: MemorySize>(
     }
 
     let mut path_string = unsafe { get_input_str!(&memory, path, path_len) };
+    Span::current().record("path", path_string.as_str());
 
     // Convert relative paths into absolute paths
     if path_string.starts_with("./") {
         path_string = ctx.data().state.fs.relative_path_to_absolute(path_string);
         trace!(
-            "wasi[{}:{}]::rel_to_abs (name={}))",
+            %path_string
-            ctx.data().pid(),
-            ctx.data().tid(),
-            path_string
         );
     }
-    debug!("=> path_open(): dirfd: {}, path: {}", dirfd, &path_string);
 
     let path_arg = std::path::PathBuf::from(&path_string);
     let maybe_inode = state.fs.get_inode_at_path(
@@ -200,11 +197,7 @@ pub fn path_open<M: MemorySize>(
                         // nothing bad happens
                         let dup_fd = wasi_try!(state.fs.clone_fd(fd));
                         trace!(
-                            "wasi[{}:{}]::path_open [special_fd] (dup_fd: {}->{})",
+                            %dup_fd
-                            ctx.data().pid(),
-                            ctx.data().tid(),
-                            fd,
-                            dup_fd
                         );
 
                         // some special files will return a constant FD rather than
@@ -237,12 +230,10 @@ pub fn path_open<M: MemorySize>(
         inode
     } else {
         // less-happy path, we have to try to create the file
-        debug!("Maybe creating file");
         if o_flags.contains(Oflags::CREATE) {
             if o_flags.contains(Oflags::DIRECTORY) {
                 return Errno::Notdir;
             }
-            debug!("Creating file");
             // strip end file name
 
             let (parent_inode, new_entity_name) = wasi_try!(state.fs.get_parent_inode_at_path(
@@ -289,12 +280,9 @@ pub fn path_open<M: MemorySize>(
                     open_flags |= Fd::TRUNCATE;
                 }
 
-                Some(wasi_try!(open_options.open(&new_file_host_path).map_err(
+                Some(wasi_try!(open_options
-                    |e| {
+                    .open(&new_file_host_path)
-                        debug!("Error opening file {}", e);
+                    .map_err(|e| { fs_error_into_wasi_err(e) })))
-                        fs_error_into_wasi_err(e)
-                    }
-                )))
             };
 
             let new_inode = {
@@ -334,13 +322,8 @@ pub fn path_open<M: MemorySize>(
         inode
     ));
 
-    wasi_try_mem!(fd_ref.write(out_fd));
+    Span::current().record("ret_fd", out_fd);
-    debug!(
-        "wasi[{}:{}]::path_open returning fd {}",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        out_fd
-    );
 
+    wasi_try_mem!(fd_ref.write(out_fd));
     Errno::Success
 }

lib/wasi/src/syscalls/wasi/path_readlink.rs

@@ -17,6 +17,7 @@ use crate::syscalls::*;
 ///     Pointer to characters containing the path that the symlink points to
 /// - `u32 buf_used`
 ///     The number of bytes written to `buf`
+#[instrument(level = "debug", skip_all, fields(dir_fd, path = field::Empty), ret)]
 pub fn path_readlink<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     dir_fd: WasiFd,
@@ -26,11 +27,6 @@ pub fn path_readlink<M: MemorySize>(
     buf_len: M::Offset,
     buf_used: WasmPtr<M::Offset, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::path_readlink",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (memory, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
 
@@ -39,15 +35,13 @@ pub fn path_readlink<M: MemorySize>(
         return Errno::Access;
     }
     let mut path_str = unsafe { get_input_str!(&memory, path, path_len) };
+    Span::current().record("path", path_str.as_str());
 
     // Convert relative paths into absolute paths
     if path_str.starts_with("./") {
         path_str = ctx.data().state.fs.relative_path_to_absolute(path_str);
         trace!(
-            "wasi[{}:{}]::rel_to_abs (name={}))",
+            %path_str
-            ctx.data().pid(),
-            ctx.data().tid(),
-            path_str
         );
     }
 
@@ -57,7 +51,6 @@ pub fn path_readlink<M: MemorySize>(
         let guard = inode.read();
         if let Kind::Symlink { relative_path, .. } = guard.deref() {
             let rel_path_str = relative_path.to_string_lossy();
-            debug!("Result => {:?}", rel_path_str);
             let buf_len: u64 = buf_len.into();
             let bytes = rel_path_str.bytes();
             if bytes.len() as u64 >= buf_len {

lib/wasi/src/syscalls/wasi/path_remove_directory.rs

@@ -2,6 +2,7 @@ use super::*;
 use crate::syscalls::*;
 
 /// Returns Errno::Notemtpy if directory is not empty
+#[instrument(level = "debug", skip_all, fields(fd, path = field::Empty), ret)]
 pub fn path_remove_directory<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
@@ -9,25 +10,18 @@ pub fn path_remove_directory<M: MemorySize>(
     path_len: M::Offset,
 ) -> Errno {
     // TODO check if fd is a dir, ensure it's within sandbox, etc.
-    debug!(
-        "wasi[{}:{}]::path_remove_directory",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (memory, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
 
     let base_dir = wasi_try!(state.fs.get_fd(fd));
     let mut path_str = unsafe { get_input_str!(&memory, path, path_len) };
+    Span::current().record("path", path_str.as_str());
 
     // Convert relative paths into absolute paths
     if path_str.starts_with("./") {
         path_str = ctx.data().state.fs.relative_path_to_absolute(path_str);
         trace!(
-            "wasi[{}:{}]::rel_to_abs (name={}))",
+            %path_str
-            ctx.data().pid(),
-            ctx.data().tid(),
-            path_str
         );
     }
 

lib/wasi/src/syscalls/wasi/path_rename.rs

@@ -16,6 +16,7 @@ use crate::syscalls::*;
 ///     Pointer to UTF8 bytes, the new file name
 /// - `u32 new_path_len`
 ///     The number of bytes to read from `new_path`
+#[instrument(level = "debug", skip_all, fields(old_fd, new_fd, old_path = field::Empty, new_path = field::Empty), ret)]
 pub fn path_rename<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     old_fd: WasiFd,
@@ -25,19 +26,16 @@ pub fn path_rename<M: MemorySize>(
     new_path: WasmPtr<u8, M>,
     new_path_len: M::Offset,
 ) -> Errno {
-    debug!(
-        "wasi::path_rename: old_fd = {}, new_fd = {}",
-        old_fd, new_fd
-    );
     let env = ctx.data();
     let (memory, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
     let mut source_str = unsafe { get_input_str!(&memory, old_path, old_path_len) };
+    Span::current().record("old_path", source_str.as_str());
     source_str = ctx.data().state.fs.relative_path_to_absolute(source_str);
     let source_path = std::path::Path::new(&source_str);
     let mut target_str = unsafe { get_input_str!(&memory, new_path, new_path_len) };
+    Span::current().record("new_path", target_str.as_str());
     target_str = ctx.data().state.fs.relative_path_to_absolute(target_str);
     let target_path = std::path::Path::new(&target_str);
-    debug!("=> rename from {} to {}", &source_str, &target_str);
 
     {
         let source_fd = wasi_try!(state.fs.get_fd(old_fd));
@@ -87,7 +85,7 @@ pub fn path_rename<M: MemorySize>(
                 return Errno::Inval
             }
             Kind::Symlink { .. } | Kind::File { .. } | Kind::Buffer { .. } => {
-                error!("Fatal internal logic error: parent of inode is not a directory");
+                debug!("fatal internal logic error: parent of inode is not a directory");
                 return Errno::Inval;
             }
         }
@@ -104,7 +102,7 @@ pub fn path_rename<M: MemorySize>(
                 return Errno::Inval
             }
             Kind::Symlink { .. } | Kind::File { .. } | Kind::Buffer { .. } => {
-                error!("Fatal internal logic error: parent of inode is not a directory");
+                debug!("fatal internal logic error: parent of inode is not a directory");
                 return Errno::Inval;
             }
         }
@@ -175,7 +173,7 @@ pub fn path_rename<M: MemorySize>(
             let result = entries.insert(target_entry_name, source_entry);
             assert!(
                 result.is_none(),
-                "Fatal error: race condition on filesystem detected or internal logic error"
+                "fatal error: race condition on filesystem detected or internal logic error"
             );
         }
     }

lib/wasi/src/syscalls/wasi/path_symlink.rs

@@ -14,6 +14,7 @@ use crate::syscalls::*;
 ///     Array of UTF-8 bytes representing the target path
 /// - `u32 new_path_len`
 ///     The number of bytes to read from `new_path`
+#[instrument(level = "debug", skip_all, fields(fd, old_path = field::Empty, new_path = field::Empty), ret)]
 pub fn path_symlink<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     old_path: WasmPtr<u8, M>,
@@ -22,15 +23,12 @@ pub fn path_symlink<M: MemorySize>(
     new_path: WasmPtr<u8, M>,
     new_path_len: M::Offset,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::path_symlink",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (memory, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
     let mut old_path_str = unsafe { get_input_str!(&memory, old_path, old_path_len) };
+    Span::current().record("old_path", old_path_str.as_str());
     let mut new_path_str = unsafe { get_input_str!(&memory, new_path, new_path_len) };
+    Span::current().record("new_path", new_path_str.as_str());
     old_path_str = ctx.data().state.fs.relative_path_to_absolute(old_path_str);
     new_path_str = ctx.data().state.fs.relative_path_to_absolute(new_path_str);
     let base_fd = wasi_try!(state.fs.get_fd(fd));
@@ -83,11 +81,6 @@ pub fn path_symlink<M: MemorySize>(
         relative_path.push("..");
     }
     relative_path.push(source_path);
-    debug!(
-        "Symlinking {} to {}",
-        new_path_str,
-        relative_path.to_string_lossy()
-    );
 
     let kind = Kind::Symlink {
         base_po_dir: fd,

lib/wasi/src/syscalls/wasi/path_unlink_file.rs

@@ -10,17 +10,13 @@ use crate::syscalls::*;
 ///     Array of UTF-8 bytes representing the path
 /// - `u32 path_len`
 ///     The number of bytes in the `path` array
+#[instrument(level = "debug", skip_all, fields(fd, path = field::Empty), ret)]
 pub fn path_unlink_file<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     fd: WasiFd,
     path: WasmPtr<u8, M>,
     path_len: M::Offset,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::path_unlink_file",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let (memory, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
 
@@ -29,17 +25,11 @@ pub fn path_unlink_file<M: MemorySize>(
         return Errno::Access;
     }
     let mut path_str = unsafe { get_input_str!(&memory, path, path_len) };
-    debug!("Requested file: {}", path_str);
+    Span::current().record("path", path_str.as_str());
 
     // Convert relative paths into absolute paths
     if path_str.starts_with("./") {
         path_str = ctx.data().state.fs.relative_path_to_absolute(path_str);
-        trace!(
-            "wasi[{}:{}]::rel_to_abs (name={}))",
-            ctx.data().pid(),
-            ctx.data().tid(),
-            path_str
-        );
     }
 
     let inode = wasi_try!(state.fs.get_inode_at_path(inodes, fd, &path_str, false));

lib/wasi/src/syscalls/wasi/poll_oneoff.rs

@@ -22,6 +22,7 @@ use crate::{
 /// Output:
 /// - `u32 nevents`
 ///     The number of events seen
+#[instrument(level = "trace", skip_all, fields(timeout_ns = field::Empty, fd_guards = field::Empty, seen = field::Empty), ret, err)]
 pub fn poll_oneoff<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     in_: WasmPtr<Subscription, M>,
@@ -49,12 +50,6 @@ pub fn poll_oneoff<M: MemorySize>(
     let triggered_events = match triggered_events {
         Ok(a) => a,
         Err(err) => {
-            tracing::trace!(
-                "wasi[{}:{}]::poll_oneoff errno={}",
-                ctx.data().pid(),
-                ctx.data().tid(),
-                err
-            );
             return Ok(err);
         }
     };
@@ -105,14 +100,7 @@ impl<'a> Future for PollBatch<'a> {
                 Poll::Pending => {}
                 Poll::Ready(e) => {
                     for evt in e {
-                        tracing::trace!(
+                        tracing::trace!(fd, userdata = evt.userdata, ty = evt.type_ as u8,);
-                            "wasi[{}:{}]::poll_oneoff triggered_fd (fd={}, userdata={}, type={:?})",
-                            pid,
-                            tid,
-                            fd,
-                            evt.userdata,
-                            evt.type_,
-                        );
                         evts.push(evt);
                     }
                 }
@@ -149,12 +137,6 @@ pub(crate) fn poll_oneoff_internal(
     // Determine if we are in silent polling mode
     let mut env = ctx.data();
     let state = ctx.data().state.deref();
-    trace!(
-        "wasi[{}:{}]::poll_oneoff (nsubscriptions={})",
-        pid,
-        tid,
-        subs.len(),
-    );
 
     // These are used when we capture what clocks (timeouts) are being
     // subscribed too
@@ -222,23 +204,14 @@ pub(crate) fn poll_oneoff_internal(
                     // If the timeout duration is zero then this is an immediate check rather than
                     // a sleep itself
                     if clock_info.timeout == 0 {
-                        tracing::trace!("wasi[{}:{}]::poll_oneoff nonblocking", pid, tid,);
                         time_to_sleep = Some(Duration::ZERO);
                     } else {
-                        tracing::trace!(
-                            "wasi[{}:{}]::poll_oneoff clock_id={:?} (userdata={}, timeout={})",
-                            pid,
-                            tid,
-                            clock_info.clock_id,
-                            s.userdata,
-                            clock_info.timeout
-                        );
                         time_to_sleep = Some(Duration::from_nanos(clock_info.timeout));
                         clock_subs.push((clock_info, s.userdata));
                     }
                     continue;
                 } else {
-                    error!("Polling not implemented for these clocks yet");
+                    error!("polling not implemented for these clocks yet");
                     return Ok(Err(Errno::Inval));
                 }
             }
@@ -289,33 +262,28 @@ pub(crate) fn poll_oneoff_internal(
                             }
                         }
                     };
-                    tracing::trace!(
-                        "wasi[{}:{}]::poll_oneoff wait_for_fd={} type={:?}",
-                        pid,
-                        tid,
-                        fd,
-                        wasi_file_ref
-                    );
                     fd_guards.push(wasi_file_ref);
                 }
             }
 
+            if fd_guards.len() > 10 {
+                let small_list: Vec<_> = fd_guards.iter().take(10).collect();
+                tracing::Span::current().record("fd_guards", format!("{:?}...", small_list));
+            } else {
+                tracing::Span::current().record("fd_guards", format!("{:?}", fd_guards));
+            }
+
             fd_guards
         };
 
         if let Some(time_to_sleep) = time_to_sleep.as_ref() {
             if *time_to_sleep == Duration::ZERO {
-                tracing::trace!("wasi[{}:{}]::poll_oneoff non_blocking", pid, tid,);
+                Span::current().record("timeout_ns", "nonblocking");
             } else {
-                tracing::trace!(
+                Span::current().record("timeout_ns", time_to_sleep.as_millis());
-                    "wasi[{}:{}]::poll_oneoff wait_for_timeout={}",
-                    pid,
-                    tid,
-                    time_to_sleep.as_millis()
-                );
             }
         } else {
-            tracing::trace!("wasi[{}:{}]::poll_oneoff wait_for_infinite", pid, tid,);
+            Span::current().record("timeout_ns", "infinite");
         }
 
         // Block polling the file descriptors
@@ -330,22 +298,13 @@ pub(crate) fn poll_oneoff_internal(
     match ret {
         Ok(evts) => {
             // If its a timeout then return an event for it
-            tracing::trace!(
+            Span::current().record("seen", evts.len());
-                "wasi[{}:{}]::poll_oneoff seen={}",
-                ctx.data().pid(),
-                ctx.data().tid(),
-                evts.len()
-            );
             Ok(Ok(evts))
         }
         Err(Errno::Timedout) => {
             // The timeout has triggerred so lets add that event
             if clock_subs.is_empty() && time_to_sleep != Some(Duration::ZERO) {
-                tracing::warn!(
+                tracing::warn!("triggered_timeout (without any clock subscriptions)",);
-                    "wasi[{}:{}]::poll_oneoff triggered_timeout (without any clock subscriptions)",
-                    pid,
-                    tid
-                );
             }
             let mut evts = Vec::new();
             for (clock_info, userdata) in clock_subs {
@@ -355,12 +314,12 @@ pub(crate) fn poll_oneoff_internal(
                     type_: Eventtype::Clock,
                     u: EventUnion { clock: 0 },
                 };
-                tracing::trace!(
+                Span::current().record(
-                    "wasi[{}:{}]::poll_oneoff triggered_clock id={:?} (userdata={})",
+                    "seen",
-                    pid,
+                    &format!(
-                    tid,
+                        "clock(id={},userdata={})",
-                    clock_info.clock_id,
+                        clock_info.clock_id as u32, evt.userdata
-                    evt.userdata,
+                    ),
                 );
                 evts.push(evt);
             }

lib/wasi/src/syscalls/wasi/proc_exit.rs

@@ -8,17 +8,11 @@ use crate::syscalls::*;
 /// Inputs:
 /// - `ExitCode`
 ///   Exit code to return to the operating system
+#[instrument(level = "debug", skip_all, fields(code))]
 pub fn proc_exit<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     code: ExitCode,
 ) -> Result<(), WasiError> {
-    debug!(
-        "wasi[{}:{}]::proc_exit (code={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        code
-    );
-
     // Set the exit code for this process
     ctx.data().thread.set_status_finished(Ok(code as u32));
 
@@ -44,7 +38,11 @@ pub fn proc_exit<M: MemorySize>(
             // Make sure its within the "active" part of the memory stack
             let offset = wasi_env.stack_base - pid_offset;
             if offset as usize > memory_stack.len() {
-                warn!("wasi[{}:{}]::vfork failed - the return value (pid) is outside of the active part of the memory stack ({} vs {})", ctx.data().pid(), ctx.data().tid(), offset, memory_stack.len());
+                warn!(
+                    "fork failed - the return value (pid) is outside of the active part of the memory stack ({} vs {})",
+                    offset,
+                    memory_stack.len()
+                );
                 return Err(WasiError::Exit(Errno::Fault as u32));
             }
 
@@ -55,7 +53,9 @@ pub fn proc_exit<M: MemorySize>(
             let pbytes = &mut memory_stack[pstart..pend];
             pbytes.clone_from_slice(&val_bytes);
         } else {
-            warn!("wasi[{}:{}]::vfork failed - the return value (pid) is not being returned on the stack - which is not supported", ctx.data().pid(), ctx.data().tid());
+            warn!(
+                "fork failed - the return value (pid) is not being returned on the stack - which is not supported"
+            );
             return Err(WasiError::Exit(Errno::Fault as u32));
         }
 

lib/wasi/src/syscalls/wasi/proc_raise.rs

@@ -7,13 +7,8 @@ use crate::syscalls::*;
 /// Inputs:
 /// - `Signal`
 ///   Signal to be raised for this process
+#[instrument(level = "debug", skip_all, fields(sig), ret, err)]
 pub fn proc_raise(mut ctx: FunctionEnvMut<'_, WasiEnv>, sig: Signal) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::proc_raise (sig={:?})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sig
-    );
     let env = ctx.data();
     env.process.signal_process(sig);
 
@@ -34,12 +29,6 @@ pub fn proc_raise_interval(
     interval: Timestamp,
     repeat: Bool,
 ) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::proc_raise_interval (sig={:?})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sig
-    );
     let env = ctx.data();
     let interval = match interval {
         0 => None,

lib/wasi/src/syscalls/wasi/random_get.rs

@@ -8,17 +8,12 @@ use crate::syscalls::*;
 ///     A pointer to a buffer where the random bytes will be written
 /// - `size_t buf_len`
 ///     The number of bytes that will be written
+#[instrument(level = "trace", skip_all, fields(buf_len), ret)]
 pub fn random_get<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     buf: WasmPtr<u8, M>,
     buf_len: M::Offset,
 ) -> Errno {
-    trace!(
-        "wasi[{}:{}]::random_get(buf_len={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        buf_len
-    );
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
     let buf_len64: u64 = buf_len.into();

lib/wasi/src/syscalls/wasix/callback_reactor.rs

@@ -7,6 +7,7 @@ use crate::syscalls::*;
 /// ### Parameters
 ///
 /// * `name` - Name of the function that will be invoked
+#[instrument(level = "debug", skip_all, fields(name = field::Empty, funct_is_some = field::Empty), ret, err)]
 pub fn callback_reactor<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     name: WasmPtr<u8, M>,
@@ -15,12 +16,7 @@ pub fn callback_reactor<M: MemorySize>(
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
     let name = unsafe { name.read_utf8_string(&memory, name_len)? };
-    debug!(
+    Span::current().record("name", name.as_str());
-        "wasi[{}:{}]::callback_reactor (name={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        name
-    );
 
     let funct = env
         .inner()
@@ -28,6 +24,7 @@ pub fn callback_reactor<M: MemorySize>(
         .exports
         .get_typed_function(&ctx, &name)
         .ok();
+    Span::current().record("funct_is_some", funct.is_some());
 
     ctx.data_mut().inner_mut().react = funct;
     Ok(())

lib/wasi/src/syscalls/wasix/callback_signal.rs

@@ -7,6 +7,7 @@ use crate::syscalls::*;
 /// ### Parameters
 ///
 /// * `name` - Name of the function that will be invoked
+#[instrument(level = "trace", skip_all, fields(name = field::Empty, funct_is_some = field::Empty), ret, err)]
 pub fn callback_signal<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     name: WasmPtr<u8, M>,
@@ -26,6 +27,7 @@ pub fn callback_signal<M: MemorySize>(
             }
         }
     };
+    Span::current().record("name", name.as_str());
 
     let funct = env
         .inner()
@@ -33,13 +35,7 @@ pub fn callback_signal<M: MemorySize>(
         .exports
         .get_typed_function(&ctx, &name)
         .ok();
-    trace!(
+    Span::current().record("funct_is_some", funct.is_some());
-        "wasi[{}:{}]::callback_signal (name={}, found={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        name,
-        funct.is_some()
-    );
 
     {
         let inner = ctx.data_mut().inner_mut();

lib/wasi/src/syscalls/wasix/callback_thread.rs

@@ -7,6 +7,7 @@ use crate::syscalls::*;
 /// ### Parameters
 ///
 /// * `name` - Name of the function that will be invoked
+#[instrument(level = "debug", skip_all, fields(name = field::Empty, funct_is_some = field::Empty), ret ,err)]
 pub fn callback_thread<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     name: WasmPtr<u8, M>,
@@ -14,13 +15,9 @@ pub fn callback_thread<M: MemorySize>(
 ) -> Result<(), MemoryAccessError> {
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
+
     let name = unsafe { name.read_utf8_string(&memory, name_len)? };
-    debug!(
+    Span::current().record("name", name.as_str());
-        "wasi[{}:{}]::callback_spawn (name={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        name
-    );
 
     let funct = env
         .inner()
@@ -28,6 +25,7 @@ pub fn callback_thread<M: MemorySize>(
         .exports
         .get_typed_function(&ctx, &name)
         .ok();
+    Span::current().record("funct_is_some", funct.is_some());
 
     ctx.data_mut().inner_mut().thread_spawn = funct;
     Ok(())

lib/wasi/src/syscalls/wasix/callback_thread_local_destroy.rs

@@ -7,6 +7,7 @@ use crate::syscalls::*;
 /// ### Parameters
 ///
 /// * `name` - Name of the function that will be invoked
+#[instrument(level = "debug", skip_all, fields(name = field::Empty, funct_is_some = field::Empty), ret, err)]
 pub fn callback_thread_local_destroy<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     name: WasmPtr<u8, M>,
@@ -14,13 +15,9 @@ pub fn callback_thread_local_destroy<M: MemorySize>(
 ) -> Result<(), MemoryAccessError> {
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
+
     let name = unsafe { name.read_utf8_string(&memory, name_len)? };
-    debug!(
+    Span::current().record("name", name.as_str());
-        "wasi[{}:{}]::callback_thread_local_destroy (name={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        name
-    );
 
     let funct = env
         .inner()
@@ -28,6 +25,7 @@ pub fn callback_thread_local_destroy<M: MemorySize>(
         .exports
         .get_typed_function(&ctx, &name)
         .ok();
+    Span::current().record("funct_is_some", funct.is_some());
 
     ctx.data_mut().inner_mut().thread_local_destroy = funct;
     Ok(())

lib/wasi/src/syscalls/wasix/chdir.rs

@@ -3,6 +3,7 @@ use crate::syscalls::*;
 
 /// ### `chdir()`
 /// Sets the current working directory
+#[instrument(level = "debug", skip_all, fields(name = field::Empty), ret)]
 pub fn chdir<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     path: WasmPtr<u8, M>,
@@ -11,12 +12,7 @@ pub fn chdir<M: MemorySize>(
     let env = ctx.data();
     let (memory, mut state) = env.get_memory_and_wasi_state(&ctx, 0);
     let path = unsafe { get_input_str!(&memory, path, path_len) };
-    debug!(
+    Span::current().record("path", path.as_str());
-        "wasi[{}:{}]::chdir [{}]",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        path
-    );
 
     // Check if the directory exists
     if state.fs.root_fs.read_dir(Path::new(path.as_str())).is_err() {

lib/wasi/src/syscalls/wasix/fd_pipe.rs

@@ -10,13 +10,12 @@ use crate::syscalls::*;
 ///     First file handle that represents one end of the pipe
 /// - `Fd`
 ///     Second file handle that represents the other end of the pipe
+#[instrument(level = "trace", skip_all, fields(fd1 = field::Empty, fd2 = field::Empty), ret)]
 pub fn fd_pipe<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     ro_fd1: WasmPtr<WasiFd, M>,
     ro_fd2: WasmPtr<WasiFd, M>,
 ) -> Errno {
-    trace!("wasi[{}:{}]::fd_pipe", ctx.data().pid(), ctx.data().tid());
-
     let env = ctx.data();
     let (memory, state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
 
@@ -47,13 +46,7 @@ pub fn fd_pipe<M: MemorySize>(
     let fd2 = wasi_try!(state
         .fs
         .create_fd(rights, rights, Fdflags::empty(), 0, inode2));
-    trace!(
+    Span::current().record("fd1", fd1).record("fd2", fd2);
-        "wasi[{}:{}]::fd_pipe (fd1={}, fd2={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd1,
-        fd2
-    );
 
     wasi_try_mem!(ro_fd1.write(&memory, fd1));
     wasi_try_mem!(ro_fd2.write(&memory, fd2));

lib/wasi/src/syscalls/wasix/futex_wait.rs

@@ -66,6 +66,7 @@ where
 /// * `futex` - Memory location that holds the value that will be checked
 /// * `expected` - Expected value that should be currently held at the memory location
 /// * `timeout` - Timeout should the futex not be triggered in the allocated time
+#[instrument(level = "trace", skip_all, fields(futex_idx = field::Empty, expected, timeout = field::Empty, woken = field::Empty), err)]
 pub fn futex_wait<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     futex_ptr: WasmPtr<u32, M>,
@@ -85,17 +86,11 @@ pub fn futex_wait<M: MemorySize>(
         OptionTag::Some => Some(Duration::from_nanos(timeout.u as u64)),
         _ => None,
     };
-
+    Span::current().record("timeout", &format!("{:?}", timeout));
-    trace!(
-        "wasi[{}:{}]::futex_wait(offset={}, timeout={:?})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        futex_ptr.offset(),
-        timeout
-    );
 
     let state = env.state.clone();
     let futex_idx: u64 = wasi_try_ok!(futex_ptr.offset().try_into().map_err(|_| Errno::Overflow));
+    Span::current().record("futex_idx", futex_idx);
 
     // Create a poller which will register ourselves against
     // this futex event and check when it has changed
@@ -121,6 +116,8 @@ pub fn futex_wait<M: MemorySize>(
         }
         Ok(_) => Bool::True,
     };
+    Span::current().record("woken", woken as u8);
+
     let memory = env.memory_view(&ctx);
     let mut env = ctx.data();
     wasi_try_mem_ok!(ret_woken.write(&memory, woken));

lib/wasi/src/syscalls/wasix/futex_wake.rs

@@ -8,6 +8,7 @@ use crate::syscalls::*;
 /// ## Parameters
 ///
 /// * `futex` - Memory location that holds a futex that others may be waiting on
+#[instrument(level = "trace", skip_all, fields(futex_idx = field::Empty, woken = field::Empty), ret)]
 pub fn futex_wake<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     futex_ptr: WasmPtr<u32, M>,
@@ -18,8 +19,9 @@ pub fn futex_wake<M: MemorySize>(
     let state = env.state.deref();
 
     let pointer: u64 = wasi_try!(futex_ptr.offset().try_into().map_err(|_| Errno::Overflow));
-    let mut woken = false;
+    Span::current().record("futex_idx", pointer);
 
+    let mut woken = false;
     let woken = {
         let mut guard = state.futexs.lock().unwrap();
         if let Some(futex) = guard.get_mut(&pointer) {
@@ -34,22 +36,7 @@ pub fn futex_wake<M: MemorySize>(
             false
         }
     };
-    if woken {
+    Span::current().record("woken", woken);
-        trace!(
-            %woken,
-            "wasi[{}:{}]::futex_wake(offset={})",
-            ctx.data().pid(),
-            ctx.data().tid(),
-            futex_ptr.offset()
-        );
-    } else {
-        trace!(
-            "wasi[{}:{}]::futex_wake(offset={}) - nothing waiting",
-            ctx.data().pid(),
-            ctx.data().tid(),
-            futex_ptr.offset()
-        );
-    }
 
     let woken = match woken {
         false => Bool::False,

lib/wasi/src/syscalls/wasix/futex_wake_all.rs

@@ -6,6 +6,7 @@ use crate::syscalls::*;
 /// ## Parameters
 ///
 /// * `futex` - Memory location that holds a futex that others may be waiting on
+#[instrument(level = "trace", skip_all, fields(futex_idx = field::Empty, woken = field::Empty), ret)]
 pub fn futex_wake_all<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     futex_ptr: WasmPtr<u32, M>,
@@ -16,8 +17,9 @@ pub fn futex_wake_all<M: MemorySize>(
     let state = env.state.deref();
 
     let pointer: u64 = wasi_try!(futex_ptr.offset().try_into().map_err(|_| Errno::Overflow));
-    let mut woken = false;
+    Span::current().record("futex_idx", pointer);
 
+    let mut woken = false;
     let woken = {
         let mut guard = state.futexs.lock().unwrap();
         if let Some(futex) = guard.remove(&pointer) {
@@ -27,22 +29,7 @@ pub fn futex_wake_all<M: MemorySize>(
             false
         }
     };
-    if woken {
+    Span::current().record("woken", woken);
-        trace!(
-            %woken,
-            "wasi[{}:{}]::futex_wake(offset={})",
-            ctx.data().pid(),
-            ctx.data().tid(),
-            futex_ptr.offset()
-        );
-    } else {
-        trace!(
-            "wasi[{}:{}]::futex_wake(offset={}) - nothing waiting",
-            ctx.data().pid(),
-            ctx.data().tid(),
-            futex_ptr.offset()
-        );
-    }
 
     let woken = match woken {
         false => Bool::False,

lib/wasi/src/syscalls/wasix/getcwd.rs

@@ -5,26 +5,22 @@ use crate::syscalls::*;
 /// Returns the current working directory
 /// If the path exceeds the size of the buffer then this function
 /// will fill the path_len with the needed size and return EOVERFLOW
+#[instrument(level = "debug", skip_all, fields(path = field::Empty, max_path_len = field::Empty), ret)]
 pub fn getcwd<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     path: WasmPtr<u8, M>,
     path_len: WasmPtr<M::Offset, M>,
 ) -> Errno {
-    debug!("wasi[{}:{}]::getcwd", ctx.data().pid(), ctx.data().tid());
     let env = ctx.data();
     let (memory, mut state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0);
 
     let (_, cur_dir) = wasi_try!(state.fs.get_current_dir(inodes, crate::VIRTUAL_ROOT_FD,));
-    trace!(
+    Span::current().record("path", cur_dir.as_str());
-        "wasi[{}:{}]::getcwd(current_dir={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        cur_dir
-    );
 
     let max_path_len = wasi_try_mem!(path_len.read(&memory));
     let path_slice = wasi_try_mem!(path.slice(&memory, max_path_len));
     let max_path_len: u64 = max_path_len.into();
+    Span::current().record("max_path_len", max_path_len);
 
     let cur_dir = cur_dir.as_bytes();
     wasi_try_mem!(path_len.write(&memory, wasi_try!(to_offset::<M>(cur_dir.len()))));

lib/wasi/src/syscalls/wasix/mod.rs

@@ -141,3 +141,5 @@ pub use thread_sleep::*;
 pub use thread_spawn::*;
 pub use tty_get::*;
 pub use tty_set::*;
+
+use tracing::{debug_span, field, instrument, trace_span, Span};

lib/wasi/src/syscalls/wasix/port_addr_add.rs

@@ -7,18 +7,17 @@ use crate::syscalls::*;
 /// ## Parameters
 ///
 /// * `addr` - Address to be added
+#[instrument(level = "debug", skip_all, fields(ip = field::Empty), ret, err)]
 pub fn port_addr_add<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     ip: WasmPtr<__wasi_cidr_t, M>,
 ) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_addr_add",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
+
     let cidr = wasi_try_ok!(crate::net::read_cidr(&memory, ip));
+    Span::current().record("ip", &format!("{:?}", cidr));
+
     let net = env.net().clone();
     wasi_try_ok!(__asyncify(&mut ctx, None, async {
         net.ip_add(cidr.ip, cidr.prefix)

lib/wasi/src/syscalls/wasix/port_addr_clear.rs

@@ -3,12 +3,8 @@ use crate::syscalls::*;
 
 /// ### `port_addr_clear()`
 /// Clears all the addresses on the local port
+#[instrument(level = "debug", skip_all, ret, err)]
 pub fn port_addr_clear(mut ctx: FunctionEnvMut<'_, WasiEnv>) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_addr_clear",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let net = env.net().clone();
     wasi_try_ok!(__asyncify(&mut ctx, None, async {

lib/wasi/src/syscalls/wasix/port_addr_list.rs

@@ -14,16 +14,12 @@ use crate::syscalls::*;
 /// ## Return
 ///
 /// The number of addresses returned.
+#[instrument(level = "debug", skip_all, fields(naddrs = field::Empty)ret, err)]
 pub fn port_addr_list<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     addrs_ptr: WasmPtr<__wasi_cidr_t, M>,
     naddrs_ptr: WasmPtr<M::Offset, M>,
 ) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_addr_list",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let mut env = ctx.data();
     let mut memory = env.memory_view(&ctx);
     let max_addrs = wasi_try_mem_ok!(naddrs_ptr.read(&memory));
@@ -35,6 +31,7 @@ pub fn port_addr_list<M: MemorySize>(
     })?);
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
+    Span::current().record("naddrs", addrs.len());
 
     let addrs_len: M::Offset = wasi_try_ok!(addrs.len().try_into().map_err(|_| Errno::Overflow));
     wasi_try_mem_ok!(naddrs_ptr.write(&memory, addrs_len));

lib/wasi/src/syscalls/wasix/port_addr_remove.rs

@@ -7,18 +7,17 @@ use crate::syscalls::*;
 /// ## Parameters
 ///
 /// * `addr` - Address to be removed
+#[instrument(level = "debug", skip_all, fields(ip = field::Empty), ret, err)]
 pub fn port_addr_remove<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     ip: WasmPtr<__wasi_addr_t, M>,
 ) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_addr_remove",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
+
     let ip = wasi_try_ok!(crate::net::read_ip(&memory, ip));
+    Span::current().record("ip", &format!("{:?}", ip));
+
     let net = env.net().clone();
     wasi_try_ok!(__asyncify(&mut ctx, None, async {
         net.ip_remove(ip).map_err(net_error_into_wasi_err)

lib/wasi/src/syscalls/wasix/port_bridge.rs

@@ -9,6 +9,7 @@ use crate::syscalls::*;
 /// * `network` - Fully qualified identifier for the network
 /// * `token` - Access token used to authenticate with the network
 /// * `security` - Level of encryption to encapsulate the network connection with
+#[instrument(level = "debug", skip_all, fields(network = field::Empty, security), ret, err)]
 pub fn port_bridge<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     network: WasmPtr<u8, M>,
@@ -17,14 +18,12 @@ pub fn port_bridge<M: MemorySize>(
     token_len: M::Offset,
     security: Streamsecurity,
 ) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_bridge",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
+
     let network = unsafe { get_input_str_ok!(&memory, network, network_len) };
+    Span::current().record("network", network.as_str());
+
     let token = unsafe { get_input_str_ok!(&memory, token, token_len) };
     let security = match security {
         Streamsecurity::Unencrypted => StreamSecurity::Unencrypted,

lib/wasi/src/syscalls/wasix/port_dhcp_acquire.rs

@@ -3,12 +3,8 @@ use crate::syscalls::*;
 
 /// ### `port_dhcp_acquire()`
 /// Acquires a set of IP addresses using DHCP
+#[instrument(level = "debug", skip_all, ret, err)]
 pub fn port_dhcp_acquire(mut ctx: FunctionEnvMut<'_, WasiEnv>) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_dhcp_acquire",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let net = env.net().clone();
     let tasks = env.tasks().clone();

lib/wasi/src/syscalls/wasix/port_gateway_set.rs

@@ -7,18 +7,16 @@ use crate::syscalls::*;
 /// ## Parameters
 ///
 /// * `addr` - Address of the default gateway
+#[instrument(level = "debug", skip_all, fields(ip = field::Empty), ret, err)]
 pub fn port_gateway_set<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     ip: WasmPtr<__wasi_addr_t, M>,
 ) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_gateway_set",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
+
     let ip = wasi_try_ok!(crate::net::read_ip(&memory, ip));
+    Span::current().record("ip", &format!("{:?}", ip));
 
     let net = env.net().clone();
     wasi_try_ok!(__asyncify(&mut ctx, None, async {

lib/wasi/src/syscalls/wasix/port_mac.rs

@@ -3,11 +3,11 @@ use crate::syscalls::*;
 
 /// ### `port_mac()`
 /// Returns the MAC address of the local port
+#[instrument(level = "debug", skip_all, fields(max = field::Empty), ret, err)]
 pub fn port_mac<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     ret_mac: WasmPtr<__wasi_hardwareaddress_t, M>,
 ) -> Result<Errno, WasiError> {
-    debug!("wasi[{}:{}]::port_mac", ctx.data().pid(), ctx.data().tid());
     let mut env = ctx.data();
     let mut memory = env.memory_view(&ctx);
 
@@ -18,6 +18,8 @@ pub fn port_mac<M: MemorySize>(
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
 
+    Span::current().record("mac", hex::encode(mac.as_ref()).as_str());
+
     let mac = __wasi_hardwareaddress_t { octs: mac };
     wasi_try_mem_ok!(ret_mac.write(&memory, mac));
     Ok(Errno::Success)

lib/wasi/src/syscalls/wasix/port_route_add.rs

@@ -3,6 +3,7 @@ use crate::syscalls::*;
 
 /// ### `port_route_add()`
 /// Adds a new route to the local port
+#[instrument(level = "debug", skip_all, fields(cidr = field::Empty, via_router = field::Empty), ret, err)]
 pub fn port_route_add<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     cidr: WasmPtr<__wasi_cidr_t, M>,
@@ -10,15 +11,15 @@ pub fn port_route_add<M: MemorySize>(
     preferred_until: WasmPtr<OptionTimestamp, M>,
     expires_at: WasmPtr<OptionTimestamp, M>,
 ) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_route_add",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
+
     let cidr = wasi_try_ok!(crate::net::read_cidr(&memory, cidr));
+    Span::current().record("cidr", &format!("{:?}", cidr));
+
     let via_router = wasi_try_ok!(crate::net::read_ip(&memory, via_router));
+    Span::current().record("via_router", &format!("{:?}", via_router));
+
     let preferred_until = wasi_try_mem_ok!(preferred_until.read(&memory));
     let preferred_until = match preferred_until.tag {
         OptionTag::None => None,

lib/wasi/src/syscalls/wasix/port_route_clear.rs

@@ -3,12 +3,8 @@ use crate::syscalls::*;
 
 /// ### `port_route_clear()`
 /// Clears all the routes in the local port
+#[instrument(level = "debug", skip_all, ret, err)]
 pub fn port_route_clear(mut ctx: FunctionEnvMut<'_, WasiEnv>) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_route_clear",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let net = env.net().clone();
     wasi_try_ok!(__asyncify(&mut ctx, None, async {

lib/wasi/src/syscalls/wasix/port_route_list.rs

@@ -10,22 +10,19 @@ use crate::syscalls::*;
 /// ## Parameters
 ///
 /// * `routes` - The buffer where routes will be stored
+#[instrument(level = "debug", skip_all, fields(nroutes = field::Empty, max_routes = field::Empty), ret, err)]
 pub fn port_route_list<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     routes_ptr: WasmPtr<Route, M>,
     nroutes_ptr: WasmPtr<M::Offset, M>,
 ) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_route_list",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let mut env = ctx.data();
     let mut memory = env.memory_view(&ctx);
     let ref_nroutes = nroutes_ptr.deref(&memory);
     let max_routes: usize = wasi_try_ok!(wasi_try_mem_ok!(ref_nroutes.read())
         .try_into()
         .map_err(|_| Errno::Inval));
+    Span::current().record("max_routes", max_routes);
     let ref_routes =
         wasi_try_mem_ok!(routes_ptr.slice(&memory, wasi_try_ok!(to_offset::<M>(max_routes))));
 
@@ -33,6 +30,8 @@ pub fn port_route_list<M: MemorySize>(
     let routes = wasi_try_ok!(__asyncify(&mut ctx, None, async {
         net.route_list().map_err(net_error_into_wasi_err)
     })?);
+    Span::current().record("nroutes", routes.len());
+
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
 

lib/wasi/src/syscalls/wasix/port_route_remove.rs

@@ -3,18 +3,16 @@ use crate::syscalls::*;
 
 /// ### `port_route_remove()`
 /// Removes an existing route from the local port
+#[instrument(level = "debug", skip_all, fields(ip = field::Empty), ret, err)]
 pub fn port_route_remove<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     ip: WasmPtr<__wasi_addr_t, M>,
 ) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_route_remove",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
+
     let ip = wasi_try_ok!(crate::net::read_ip(&memory, ip));
+    Span::current().record("ip", &format!("{:?}", ip));
 
     let net = env.net().clone();
     wasi_try_ok!(__asyncify(&mut ctx, None, async {

lib/wasi/src/syscalls/wasix/port_unbridge.rs

@@ -3,12 +3,8 @@ use crate::syscalls::*;
 
 /// ### `port_unbridge()`
 /// Disconnects from a remote network
+#[instrument(level = "debug", skip_all, ret, err)]
 pub fn port_unbridge(mut ctx: FunctionEnvMut<'_, WasiEnv>) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::port_unbridge",
-        ctx.data().pid(),
-        ctx.data().tid()
-    );
     let env = ctx.data();
     let net = env.net().clone();
     wasi_try_ok!(__asyncify(&mut ctx, None, async move {

lib/wasi/src/syscalls/wasix/proc_exec.rs

@@ -15,6 +15,7 @@ use crate::{
 /// ## Return
 ///
 /// Returns a bus process id that can be used to invoke calls
+#[instrument(level = "debug", skip_all, fields(name = field::Empty, args_len), ret, err)]
 pub fn proc_exec<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     name: WasmPtr<u8, M>,
@@ -27,13 +28,7 @@ pub fn proc_exec<M: MemorySize>(
         warn!("failed to execve as the name could not be read - {}", err);
         WasiError::Exit(Errno::Fault as ExitCode)
     })?;
-    trace!(
+    Span::current().record("name", name.as_str());
-        "wasi[{}:{}]::proc_exec (name={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        name
-    );
-
     let args = args.read_utf8_string(&memory, args_len).map_err(|err| {
         warn!("failed to execve as the args could not be read - {}", err);
         WasiError::Exit(Errno::Fault as ExitCode)
@@ -47,13 +42,8 @@ pub fn proc_exec<M: MemorySize>(
     // Convert relative paths into absolute paths
     if name.starts_with("./") {
         name = ctx.data().state.fs.relative_path_to_absolute(name);
-        trace!(
-            "wasi[{}:{}]::rel_to_abs (name={}))",
-            ctx.data().pid(),
-            ctx.data().tid(),
-            name
-        );
     }
+    trace!(name);
 
     // Convert the preopen directories
     let preopen = ctx.data().state.preopen.clone();
@@ -103,12 +93,7 @@ pub fn proc_exec<M: MemorySize>(
                 Ok(a) => Some(a),
                 Err(err) => {
                     if err != VirtualBusError::NotFound {
-                        error!(
+                        error!("builtin failed - {}", err);
-                            "wasi[{}:{}]::proc_exec - builtin failed - {}",
-                            ctx.data().pid(),
-                            ctx.data().tid(),
-                            err
-                        );
                     }
 
                     let new_store = new_store.take().unwrap();
@@ -149,21 +134,11 @@ pub fn proc_exec<M: MemorySize>(
         // exit code can be processed
         let process = match process {
             Some(a) => {
-                trace!(
+                trace!("spawned sub-process (pid={})", child_pid.raw());
-                    "wasi[{}:{}]::spawned sub-process (pid={})",
-                    ctx.data().pid(),
-                    ctx.data().tid(),
-                    child_pid.raw()
-                );
                 a
             }
             None => {
-                debug!(
+                debug!("process failed with (err={})", err_exit_code);
-                    "wasi[{}:{}]::process failed with (err={})",
-                    ctx.data().pid(),
-                    ctx.data().tid(),
-                    err_exit_code
-                );
                 OwnedTaskStatus::new(TaskStatus::Finished(Ok(err_exit_code))).handle()
             }
         };
@@ -185,7 +160,11 @@ pub fn proc_exec<M: MemorySize>(
             // Make sure its within the "active" part of the memory stack
             let offset = stack_base - pid_offset;
             if offset as usize > memory_stack.len() {
-                warn!("vfork failed - the return value (pid) is outside of the active part of the memory stack ({} vs {})", offset, memory_stack.len());
+                warn!(
+                    "vfork failed - the return value (pid) is outside of the active part of the memory stack ({} vs {})",
+                    offset,
+                    memory_stack.len()
+                );
             } else {
                 // Update the memory stack with the new PID
                 let val_bytes = child_pid.raw().to_ne_bytes();
@@ -195,7 +174,9 @@ pub fn proc_exec<M: MemorySize>(
                 pbytes.clone_from_slice(&val_bytes);
             }
         } else {
-            warn!("vfork failed - the return value (pid) is not being returned on the stack - which is not supported");
+            warn!(
+                "vfork failed - the return value (pid) is not being returned on the stack - which is not supported",
+            );
         }
 
         // Jump back to the vfork point and current on execution
@@ -245,12 +226,7 @@ pub fn proc_exec<M: MemorySize>(
                 Ok(a) => Ok(Ok(a)),
                 Err(err) => {
                     if err != VirtualBusError::NotFound {
-                        error!(
+                        error!("builtin failed - {}", err);
-                            "wasi[{}:{}]::proc_exec - builtin failed - {}",
-                            ctx.data().pid(),
-                            ctx.data().tid(),
-                            err
-                        );
                     }
 
                     let new_store = new_store.take().unwrap();

lib/wasi/src/syscalls/wasix/proc_fork.rs

@@ -7,6 +7,7 @@ use wasmer::vm::VMMemory;
 /// Forks the current process into a new subprocess. If the function
 /// returns a zero then its the new subprocess. If it returns a positive
 /// number then its the current process and the $pid represents the child.
+#[instrument(level = "debug", skip_all, fields(copy_memory, pid = field::Empty), ret, err)]
 pub fn proc_fork<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     mut copy_memory: Bool,
@@ -15,39 +16,10 @@ pub fn proc_fork<M: MemorySize>(
     wasi_try_ok!(WasiEnv::process_signals_and_exit(&mut ctx)?);
 
     // If we were just restored then we need to return the value instead
-    let fork_op = if copy_memory == Bool::True {
-        "fork"
-    } else {
-        "vfork"
-    };
     if handle_rewind::<M>(&mut ctx) {
-        let env = ctx.data();
-        let memory = env.memory_view(&ctx);
-        let ret_pid = wasi_try_mem_ok!(pid_ptr.read(&memory));
-        if ret_pid == 0 {
-            trace!(
-                "wasi[{}:{}]::proc_{} - entering child",
-                ctx.data().pid(),
-                ctx.data().tid(),
-                fork_op
-            );
-        } else {
-            trace!(
-                "wasi[{}:{}]::proc_{} - entering parent(child={})",
-                ctx.data().pid(),
-                ctx.data().tid(),
-                fork_op,
-                ret_pid
-            );
-        }
         return Ok(Errno::Success);
     }
-    trace!(
+    trace!("capturing",);
-        "wasi[{}:{}]::proc_{} - capturing",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fork_op
-    );
 
     // Fork the environment which will copy all the open file handlers
     // and associate a new context but otherwise shares things like the
@@ -56,11 +28,7 @@ pub fn proc_fork<M: MemorySize>(
     let (mut child_env, mut child_handle) = match ctx.data().fork() {
         Ok(p) => p,
         Err(err) => {
-            debug!(
+            debug!("could not fork process: {err}");
-                pid=%ctx.data().pid(),
-                tid=%ctx.data().tid(),
-                "could not fork process: {err}"
-            );
             // TODO: evaluate the appropriate error code, document it in the spec.
             return Ok(Errno::Perm);
         }
@@ -119,10 +87,7 @@ pub fn proc_fork<M: MemorySize>(
             ) {
                 Errno::Success => OnCalledAction::InvokeAgain,
                 err => {
-                    warn!(
+                    warn!("failed - could not rewind the stack - errno={}", err);
-                        "{} failed - could not rewind the stack - errno={}",
-                        fork_op, err
-                    );
                     OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32)))
                 }
             }
@@ -135,6 +100,13 @@ pub fn proc_fork<M: MemorySize>(
 
     // Perform the unwind action
     unwind::<M, _>(ctx, move |mut ctx, mut memory_stack, rewind_stack| {
+        let span = debug_span!(
+            "unwind",
+            memory_stack_len = memory_stack.len(),
+            rewind_stack_len = rewind_stack.len()
+        );
+        let _span_guard = span.enter();
+
         // Grab all the globals and serialize them
         let store_data = crate::utils::store::capture_snapshot(&mut ctx.as_store_mut())
             .serialize()
@@ -146,25 +118,13 @@ pub fn proc_fork<M: MemorySize>(
         let fork_memory: VMMemory = match env
             .memory()
             .try_clone(&ctx)
-            .ok_or_else(|| {
+            .ok_or_else(|| MemoryError::Generic("the memory could not be cloned".to_string()))
-                error!(
-                    "wasi[{}:{}]::{} failed - the memory could not be cloned",
-                    ctx.data().pid(),
-                    ctx.data().tid(),
-                    fork_op
-                );
-                MemoryError::Generic("the memory could not be cloned".to_string())
-            })
             .and_then(|mut memory| memory.duplicate())
         {
             Ok(memory) => memory.into(),
             Err(err) => {
                 warn!(
-                    "wasi[{}:{}]::{} failed - could not fork the memory - {}",
+                    %err
-                    ctx.data().pid(),
-                    ctx.data().tid(),
-                    fork_op,
-                    err
                 );
                 return OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32)));
             }
@@ -208,16 +168,13 @@ pub fn proc_fork<M: MemorySize>(
                     import_object.define("env", "memory", memory.clone());
                     memory
                 } else {
-                    error!(
+                    error!("wasm instantiate failed - no memory supplied",);
-                        "wasi[{}:{}]::wasm instantiate failed - no memory supplied",
-                        pid, tid
-                    );
                     return;
                 };
                 let instance = match Instance::new(&mut store, &module, &import_object) {
                     Ok(a) => a,
                     Err(err) => {
-                        error!("wasi[{}:{}]::wasm instantiate error ({})", pid, tid, err);
+                        error!("wasm instantiate error ({})", err);
                         return;
                     }
                 };
@@ -230,12 +187,7 @@ pub fn proc_fork<M: MemorySize>(
 
                 // Rewind the stack and carry on
                 {
-                    trace!(
+                    trace!("rewinding child");
-                        "wasi[{}:{}]::{}: rewinding child",
-                        ctx.data(&store).pid(),
-                        ctx.data(&store).tid(),
-                        fork_op
-                    );
                     let ctx = ctx.env.clone().into_mut(&mut store);
                     match rewind::<M>(
                         ctx,
@@ -245,7 +197,10 @@ pub fn proc_fork<M: MemorySize>(
                     ) {
                         Errno::Success => OnCalledAction::InvokeAgain,
                         err => {
-                            warn!("wasi[{}:{}]::wasm rewind failed - could not rewind the stack - errno={}", pid, tid, err);
+                            warn!(
+                                "wasm rewind failed - could not rewind the stack - errno={}",
+                                err
+                            );
                             return;
                         }
                     };
@@ -254,31 +209,15 @@ pub fn proc_fork<M: MemorySize>(
                 // Invoke the start function
                 let mut ret = Errno::Success;
                 if ctx.data(&store).thread.is_main() {
-                    trace!(
+                    trace!("re-invoking main");
-                        "wasi[{}:{}]::{}: re-invoking main",
-                        ctx.data(&store).pid(),
-                        ctx.data(&store).tid(),
-                        fork_op
-                    );
                     let start = ctx.data(&store).inner().start.clone().unwrap();
                     start.call(&mut store);
                 } else {
-                    trace!(
+                    trace!("re-invoking thread_spawn");
-                        "wasi[{}:{}]::{}: re-invoking thread_spawn",
-                        ctx.data(&store).pid(),
-                        ctx.data(&store).tid(),
-                        fork_op
-                    );
                     let start = ctx.data(&store).inner().thread_spawn.clone().unwrap();
                     start.call(&mut store, 0, 0);
                 }
-                trace!(
+                trace!("child exited (code = {})", ret);
-                    "wasi[{}:{}]::proc_{} - child exited (code = {})",
-                    ctx.data(&store).pid(),
-                    ctx.data(&store).tid(),
-                    fork_op,
-                    ret
-                );
 
                 // Clean up the environment
                 ctx.cleanup((&mut store), Some(ret as ExitCode));
@@ -293,9 +232,7 @@ pub fn proc_fork<M: MemorySize>(
                 .task_wasm(Box::new(task), store, module, spawn_type)
                 .map_err(|err| {
                     warn!(
-                        "wasi[{}:{}]::failed to fork as the process could not be spawned - {}",
+                        "failed to fork as the process could not be spawned - {}",
-                        ctx.data().pid(),
-                        ctx.data().tid(),
                         err
                     );
                     err
@@ -308,12 +245,7 @@ pub fn proc_fork<M: MemorySize>(
         let process = OwnedTaskStatus::default();
 
         {
-            trace!(
+            trace!("spawned sub-process (pid={})", child_pid.raw());
-                "wasi[{}:{}]::spawned sub-process (pid={})",
-                ctx.data().pid(),
-                ctx.data().tid(),
-                child_pid.raw()
-            );
             let mut inner = ctx.data().process.write();
             inner.bus_processes.insert(child_pid, process.handle());
         }
@@ -325,7 +257,11 @@ pub fn proc_fork<M: MemorySize>(
             // Make sure its within the "active" part of the memory stack
             let offset = env.stack_base - pid_offset;
             if offset as usize > memory_stack.len() {
-                warn!("{} failed - the return value (pid) is outside of the active part of the memory stack ({} vs {})", fork_op, offset, memory_stack.len());
+                warn!(
+                        "failed - the return value (pid) is outside of the active part of the memory stack ({} vs {})",
+                        offset,
+                        memory_stack.len()
+                    );
                 return OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32)));
             }
 
@@ -336,7 +272,9 @@ pub fn proc_fork<M: MemorySize>(
             let pbytes = &mut memory_stack[pstart..pend];
             pbytes.clone_from_slice(&val_bytes);
         } else {
-            warn!("{} failed - the return value (pid) is not being returned on the stack - which is not supported", fork_op);
+            warn!(
+                    "failed - the return value (pid) is not being returned on the stack - which is not supported"
+                );
             return OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32)));
         }
 
@@ -349,10 +287,7 @@ pub fn proc_fork<M: MemorySize>(
         ) {
             Errno::Success => OnCalledAction::InvokeAgain,
             err => {
-                warn!(
+                warn!("failed - could not rewind the stack - errno={}", err);
-                    "{} failed - could not rewind the stack - errno={}",
-                    fork_op, err
-                );
                 OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32)))
             }
         }

lib/wasi/src/syscalls/wasix/proc_id.rs

@@ -3,12 +3,14 @@ use crate::syscalls::*;
 
 /// ### `proc_id()`
 /// Returns the handle of the current process
+#[instrument(level = "debug", skip_all, fields(pid = field::Empty), ret)]
 pub fn proc_id<M: MemorySize>(ctx: FunctionEnvMut<'_, WasiEnv>, ret_pid: WasmPtr<Pid, M>) -> Errno {
-    debug!("wasi[{}:{}]::getpid", ctx.data().pid(), ctx.data().tid());
-
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
+
     let pid = env.process.pid();
+    Span::current().record("pid", pid.raw());
+
     wasi_try_mem!(ret_pid.write(&memory, pid.raw() as Pid));
     Errno::Success
 }

lib/wasi/src/syscalls/wasix/proc_join.rs

@@ -7,6 +7,7 @@ use crate::syscalls::*;
 /// ## Parameters
 ///
 /// * `pid` - Handle of the child process to wait on
+#[instrument(level = "trace", skip_all, fields(filter_pid = field::Empty, ret_pid = field::Empty, exit_code = field::Empty), ret, err)]
 pub fn proc_join<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     pid_ptr: WasmPtr<Pid, M>,
@@ -17,12 +18,7 @@ pub fn proc_join<M: MemorySize>(
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
     let pid = wasi_try_mem_ok!(pid_ptr.read(&memory));
-    trace!(
+    Span::current().record("filter_pid", pid);
-        "wasi[{}:{}]::proc_join (pid={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        pid
-    );
 
     // If the ID is maximum then it means wait for any of the children
     if pid == u32::MAX {
@@ -35,23 +31,16 @@ pub fn proc_join<M: MemorySize>(
             )
             .map_err(|err| {
                 trace!(
-                    "wasi[{}:{}]::child join failed (pid={}) - {}",
+                    %pid,
-                    ctx.data().pid(),
+                    %err
-                    ctx.data().tid(),
-                    pid,
-                    err
                 );
                 err
             })?);
         return match child_exit {
             Some((pid, exit_code)) => {
-                trace!(
+                Span::current()
-                    "wasi[{}:{}]::child ({}) exited with {}",
+                    .record("ret_pid", pid.raw())
-                    ctx.data().pid(),
+                    .record("exit_code", exit_code);
-                    ctx.data().tid(),
-                    pid,
-                    exit_code
-                );
                 let env = ctx.data();
                 let memory = env.memory_view(&ctx);
                 wasi_try_mem_ok!(pid_ptr.write(&memory, pid.raw() as Pid));
@@ -59,11 +48,6 @@ pub fn proc_join<M: MemorySize>(
                 Ok(Errno::Success)
             }
             None => {
-                trace!(
-                    "wasi[{}:{}]::no children",
-                    ctx.data().pid(),
-                    ctx.data().tid()
-                );
                 let env = ctx.data();
                 let memory = env.memory_view(&ctx);
                 wasi_try_mem_ok!(pid_ptr.write(&memory, -1i32 as Pid));
@@ -84,16 +68,15 @@ pub fn proc_join<M: MemorySize>(
         })
         .map_err(|err| {
             trace!(
-                "wasi[{}:{}]::child join failed (pid={}) - {}",
+                %pid,
-                ctx.data().pid(),
+                %err
-                ctx.data().tid(),
-                pid,
-                err
             );
             err
         })?);
 
-        trace!("child ({}) exited with {}", pid.raw(), exit_code);
+        Span::current()
+            .record("ret_pid", pid.raw())
+            .record("exit_code", exit_code);
         let env = ctx.data();
         let mut children = env.process.children.write().unwrap();
         children.retain(|a| *a != pid);
@@ -103,10 +86,8 @@ pub fn proc_join<M: MemorySize>(
         return Ok(Errno::Success);
     }
 
-    debug!(
+    Span::current().record("ret_pid", pid.raw());
-        "process already terminated or not registered (pid={})",
+
-        pid.raw()
-    );
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
     wasi_try_mem_ok!(exit_code_ptr.write(&memory, Errno::Child as ExitCode));

lib/wasi/src/syscalls/wasix/proc_parent.rs

@@ -3,21 +3,22 @@ use crate::syscalls::*;
 
 /// ### `proc_parent()`
 /// Returns the parent handle of the supplied process
+#[instrument(level = "debug", skip_all, fields(pid, parent = field::Empty), ret)]
 pub fn proc_parent<M: MemorySize>(
     ctx: FunctionEnvMut<'_, WasiEnv>,
     pid: Pid,
     ret_parent: WasmPtr<Pid, M>,
 ) -> Errno {
-    debug!("wasi[{}:{}]::getppid", ctx.data().pid(), ctx.data().tid());
-
     let env = ctx.data();
     let pid: WasiProcessId = pid.into();
     if pid == env.process.pid() {
         let memory = env.memory_view(&ctx);
+        Span::current().record("parent", env.process.ppid().raw());
         wasi_try_mem!(ret_parent.write(&memory, env.process.ppid().raw() as Pid));
         Errno::Success
     } else if let Some(process) = env.control_plane.get_process(pid) {
         let memory = env.memory_view(&ctx);
+        Span::current().record("parent", process.pid().raw());
         wasi_try_mem!(ret_parent.write(&memory, process.pid().raw() as Pid));
         Errno::Success
     } else {

lib/wasi/src/syscalls/wasix/proc_signal.rs

@@ -8,19 +8,12 @@ use crate::syscalls::*;
 ///
 /// * `pid` - Handle of the child process to wait on
 /// * `sig` - Signal to send the child process
+#[instrument(level = "trace", skip_all, fields(pid, sig), ret, err)]
 pub fn proc_signal<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     pid: Pid,
     sig: Signal,
 ) -> Result<Errno, WasiError> {
-    trace!(
-        "wasi[{}:{}]::proc_signal(pid={}, sig={:?})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        pid,
-        sig
-    );
-
     let process = {
         let pid: WasiProcessId = pid.into();
         ctx.data().control_plane.get_process(pid)

lib/wasi/src/syscalls/wasix/proc_spawn.rs

@@ -22,6 +22,7 @@ use crate::syscalls::*;
 /// ## Return
 ///
 /// Returns a bus process id that can be used to invoke calls
+#[instrument(level = "debug", skip_all, fields(name = field::Empty, working_dir = field::Empty), ret, err)]
 pub fn proc_spawn<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     name: WasmPtr<u8, M>,
@@ -45,19 +46,13 @@ pub fn proc_spawn<M: MemorySize>(
     let args = unsafe { get_input_str_bus_ok!(&memory, args, args_len) };
     let preopen = unsafe { get_input_str_bus_ok!(&memory, preopen, preopen_len) };
     let working_dir = unsafe { get_input_str_bus_ok!(&memory, working_dir, working_dir_len) };
-    debug!(
+
-        "wasi[{}:{}]::process_spawn (name={})",
+    Span::current()
-        ctx.data().pid(),
+        .record("name", name.as_str())
-        ctx.data().tid(),
+        .record("working_dir", working_dir.as_str());
-        name
-    );
 
     if chroot == Bool::True {
-        warn!(
+        warn!("chroot is not currently supported",);
-            "wasi[{}:{}]::chroot is not currently supported",
-            ctx.data().pid(),
-            ctx.data().tid()
-        );
         return Ok(BusErrno::Unsupported);
     }
 
@@ -133,9 +128,7 @@ pub fn proc_spawn_internal(
         if !preopen.is_empty() {
             for preopen in preopen {
                 warn!(
-                    "wasi[{}:{}]::preopens are not yet supported for spawned processes [{}]",
+                    "preopens are not yet supported for spawned processes [{}]",
-                    ctx.data().pid(),
-                    ctx.data().tid(),
                     preopen
                 );
             }
@@ -181,13 +174,7 @@ pub fn proc_spawn_internal(
                         .create_fd_ext(rights, rights, Fdflags::empty(), 0, inode2, fd)
                         .map_err(|_| BusErrno::Internal)?;
 
-                    trace!(
+                    trace!("fd_pipe (fd1={}, fd2={})", pipe, fd);
-                        "wasi[{}:{}]::fd_pipe (fd1={}, fd2={})",
-                        ctx.data().pid(),
-                        ctx.data().tid(),
-                        pipe,
-                        fd
-                    );
                     Ok(OptionFd {
                         tag: OptionTag::Some,
                         fd: pipe,
@@ -234,12 +221,7 @@ pub fn proc_spawn_internal(
             Ok(a) => a,
             Err(err) => {
                 if err != VirtualBusError::NotFound {
-                    error!(
+                    error!("builtin failed - {}", err);
-                        "wasi[{}:{}]::proc_spawn - builtin failed - {}",
-                        ctx.data().pid(),
-                        ctx.data().tid(),
-                        err
-                    );
                 }
                 // Now we actually spawn the process
                 let child_work =

lib/wasi/src/syscalls/wasix/resolve.rs

@@ -19,6 +19,7 @@ use crate::syscalls::*;
 /// ## Return
 ///
 /// The number of IP addresses returned during the DNS resolution.
+#[instrument(level = "debug", skip_all, fields(host = field::Empty, port), ret, err)]
 pub fn resolve<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     host: WasmPtr<u8, M>,
@@ -34,13 +35,7 @@ pub fn resolve<M: MemorySize>(
         let memory = env.memory_view(&ctx);
         unsafe { get_input_str_ok!(&memory, host, host_len) }
     };
-
+    Span::current().record("host", host_str.as_str());
-    debug!(
-        "wasi[{}:{}]::resolve (host={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        host_str
-    );
 
     let port = if port > 0 { Some(port) } else { None };
 

lib/wasi/src/syscalls/wasix/sched_yield.rs

@@ -3,6 +3,7 @@ use crate::syscalls::*;
 
 /// ### `sched_yield()`
 /// Yields execution of the thread
+#[instrument(level = "trace", skip_all, ret, err)]
 pub fn sched_yield(mut ctx: FunctionEnvMut<'_, WasiEnv>) -> Result<Errno, WasiError> {
     //trace!("wasi[{}:{}]::sched_yield", ctx.data().pid(), ctx.data().tid());
     thread_sleep_internal(ctx, 0)

lib/wasi/src/syscalls/wasix/sock_accept.rs

@@ -13,6 +13,7 @@ use crate::syscalls::*;
 /// ## Return
 ///
 /// New socket connection
+#[instrument(level = "debug", skip_all, fields(sock, fd = field::Empty), ret, err)]
 pub fn sock_accept<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
@@ -20,14 +21,6 @@ pub fn sock_accept<M: MemorySize>(
     ro_fd: WasmPtr<WasiFd, M>,
     ro_addr: WasmPtr<__wasi_addr_port_t, M>,
 ) -> Result<Errno, WasiError> {
-    debug!(
-        "wasi[{}:{}]::sock_accept (fd={}, flags={:?})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock,
-        fd_flags
-    );
-
     wasi_try_ok!(WasiEnv::process_signals_and_exit(&mut ctx)?);
 
     let tasks = ctx.data().tasks().clone();
@@ -72,13 +65,7 @@ pub fn sock_accept<M: MemorySize>(
 
     let rights = Rights::all_socket();
     let fd = wasi_try_ok!(state.fs.create_fd(rights, rights, new_flags, 0, inode));
-
+    Span::current().record("fd", fd);
-    debug!(
-        "wasi[{}:{}]::sock_accept (ret=ESUCCESS, peer={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        fd
-    );
 
     wasi_try_mem_ok!(ro_fd.write(&memory, fd));
     wasi_try_ok!(crate::net::write_ip_port(

lib/wasi/src/syscalls/wasix/sock_addr_local.rs

@@ -12,24 +12,21 @@ use crate::syscalls::*;
 /// ## Parameters
 ///
 /// * `fd` - Socket that the address is bound to
+#[instrument(level = "debug", skip_all, fields(sock, addr = field::Empty), ret)]
 pub fn sock_addr_local<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     ret_addr: WasmPtr<__wasi_addr_port_t, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_addr_local (fd={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock
-    );
-
     let addr = wasi_try!(__sock_actor(
         &mut ctx,
         sock,
         Rights::empty(),
         |socket, _| socket.addr_local()
     ));
+
+    Span::current().record("addr", &format!("{:?}", addr));
+
     let memory = ctx.data().memory_view(&ctx);
     wasi_try!(crate::net::write_ip_port(
         &memory,

lib/wasi/src/syscalls/wasix/sock_addr_peer.rs

@@ -12,24 +12,19 @@ use crate::syscalls::*;
 /// ## Parameters
 ///
 /// * `fd` - Socket that the address is bound to
+#[instrument(level = "debug", skip_all, fields(sock, addr = field::Empty), ret)]
 pub fn sock_addr_peer<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     ro_addr: WasmPtr<__wasi_addr_port_t, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_addr_peer (fd={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock
-    );
-
     let addr = wasi_try!(__sock_actor(
         &mut ctx,
         sock,
         Rights::empty(),
         |socket, _| socket.addr_peer()
     ));
+    Span::current().record("addr", &format!("{:?}", addr));
 
     let env = ctx.data();
     let memory = env.memory_view(&ctx);

lib/wasi/src/syscalls/wasix/sock_bind.rs

@@ -9,22 +9,18 @@ use crate::syscalls::*;
 ///
 /// * `fd` - File descriptor of the socket to be bind
 /// * `addr` - Address to bind the socket to
+#[instrument(level = "debug", skip_all, fields(sock, addr = field::Empty), ret)]
 pub fn sock_bind<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     addr: WasmPtr<__wasi_addr_port_t, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_bind (fd={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock
-    );
-
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
     let addr = wasi_try!(crate::net::read_ip_port(&memory, addr));
     let addr = SocketAddr::new(addr.0, addr.1);
+    Span::current().record("addr", &format!("{:?}", addr));
+
     let net = env.net().clone();
 
     let tasks = ctx.data().tasks().clone();

lib/wasi/src/syscalls/wasix/sock_connect.rs

@@ -13,23 +13,18 @@ use crate::syscalls::*;
 ///
 /// * `fd` - Socket descriptor
 /// * `addr` - Address of the socket to connect to
+#[instrument(level = "debug", skip_all, fields(sock, addr = field::Empty), ret)]
 pub fn sock_connect<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     addr: WasmPtr<__wasi_addr_port_t, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_connect (fd={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock
-    );
-
     let env = ctx.data();
     let net = env.net().clone();
     let memory = env.memory_view(&ctx);
     let addr = wasi_try!(crate::net::read_ip_port(&memory, addr));
     let addr = SocketAddr::new(addr.0, addr.1);
+    Span::current().record("addr", &format!("{:?}", addr));
 
     let tasks = ctx.data().tasks().clone();
     wasi_try!(__sock_upgrade(

lib/wasi/src/syscalls/wasix/sock_get_opt_flag.rs

@@ -9,20 +9,13 @@ use crate::syscalls::*;
 ///
 /// * `fd` - Socket descriptor
 /// * `sockopt` - Socket option to be retrieved
+#[instrument(level = "debug", skip_all, fields(sock, opt), ret)]
 pub fn sock_get_opt_flag<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     opt: Sockoption,
     ret_flag: WasmPtr<Bool, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_get_opt_flag(fd={}, ty={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock,
-        opt
-    );
-
     let option: crate::net::socket::WasiSocketOption = opt.into();
     let flag = wasi_try!(__sock_actor(
         &mut ctx,

lib/wasi/src/syscalls/wasix/sock_get_opt_size.rs

@@ -9,19 +9,13 @@ use crate::syscalls::*;
 ///
 /// * `fd` - Socket descriptor
 /// * `sockopt` - Socket option to be retrieved
+#[instrument(level = "debug", skip_all, fields(sock, opt), ret)]
 pub fn sock_get_opt_size<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     opt: Sockoption,
     ret_size: WasmPtr<Filesize, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_get_opt_size(fd={}, ty={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock,
-        opt
-    );
     let size = wasi_try!(__sock_actor(
         &mut ctx,
         sock,

lib/wasi/src/syscalls/wasix/sock_get_opt_time.rs

@@ -8,20 +8,13 @@ use crate::{net::socket::TimeType, syscalls::*};
 ///
 /// * `fd` - Socket descriptor
 /// * `sockopt` - Socket option to be retrieved
+#[instrument(level = "debug", skip_all, fields(sock, opt), ret)]
 pub fn sock_get_opt_time<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     opt: Sockoption,
     ret_time: WasmPtr<OptionTimestamp, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_get_opt_time(fd={}, ty={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock,
-        opt
-    );
-
     let ty = match opt {
         Sockoption::RecvTimeout => TimeType::ReadTimeout,
         Sockoption::SendTimeout => TimeType::WriteTimeout,

lib/wasi/src/syscalls/wasix/sock_join_multicast_v4.rs

@@ -9,19 +9,13 @@ use crate::syscalls::*;
 /// * `fd` - Socket descriptor
 /// * `multiaddr` - Multicast group to joined
 /// * `interface` - Interface that will join
+#[instrument(level = "debug", skip_all, fields(sock), ret)]
 pub fn sock_join_multicast_v4<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     multiaddr: WasmPtr<__wasi_addr_ip4_t, M>,
     iface: WasmPtr<__wasi_addr_ip4_t, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_join_multicast_v4 (fd={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock
-    );
-
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
     let multiaddr = wasi_try!(crate::net::read_ip_v4(&memory, multiaddr));

lib/wasi/src/syscalls/wasix/sock_join_multicast_v6.rs

@@ -9,19 +9,13 @@ use crate::syscalls::*;
 /// * `fd` - Socket descriptor
 /// * `multiaddr` - Multicast group to joined
 /// * `interface` - Interface that will join
+#[instrument(level = "debug", skip_all, fields(sock, iface), ret)]
 pub fn sock_join_multicast_v6<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     multiaddr: WasmPtr<__wasi_addr_ip6_t, M>,
     iface: u32,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_join_multicast_v6 (fd={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock
-    );
-
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
     let multiaddr = wasi_try!(crate::net::read_ip_v6(&memory, multiaddr));

lib/wasi/src/syscalls/wasix/sock_leave_multicast_v4.rs

@@ -9,19 +9,13 @@ use crate::syscalls::*;
 /// * `fd` - Socket descriptor
 /// * `multiaddr` - Multicast group to leave
 /// * `interface` - Interface that will left
+#[instrument(level = "debug", skip_all, fields(sock), ret)]
 pub fn sock_leave_multicast_v4<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     multiaddr: WasmPtr<__wasi_addr_ip4_t, M>,
     iface: WasmPtr<__wasi_addr_ip4_t, M>,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_leave_multicast_v4 (fd={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock
-    );
-
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
     let multiaddr = wasi_try!(crate::net::read_ip_v4(&memory, multiaddr));

lib/wasi/src/syscalls/wasix/sock_leave_multicast_v6.rs

@@ -9,19 +9,13 @@ use crate::syscalls::*;
 /// * `fd` - Socket descriptor
 /// * `multiaddr` - Multicast group to leave
 /// * `interface` - Interface that will left
+#[instrument(level = "debug", skip_all, fields(sock, iface), ret)]
 pub fn sock_leave_multicast_v6<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     multiaddr: WasmPtr<__wasi_addr_ip6_t, M>,
     iface: u32,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_leave_multicast_v6 (fd={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock
-    );
-
     let env = ctx.data();
     let memory = env.memory_view(&ctx);
     let multiaddr = wasi_try!(crate::net::read_ip_v6(&memory, multiaddr));

lib/wasi/src/syscalls/wasix/sock_listen.rs

@@ -13,18 +13,12 @@ use crate::syscalls::*;
 ///
 /// * `fd` - File descriptor of the socket to be bind
 /// * `backlog` - Maximum size of the queue for pending connections
+#[instrument(level = "debug", skip_all, fields(sock, backlog), ret)]
 pub fn sock_listen<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     sock: WasiFd,
     backlog: M::Offset,
 ) -> Errno {
-    debug!(
-        "wasi[{}:{}]::sock_listen (fd={})",
-        ctx.data().pid(),
-        ctx.data().tid(),
-        sock
-    );
-
     let env = ctx.data();
     let net = env.net().clone();
     let backlog: usize = wasi_try!(backlog.try_into().map_err(|_| Errno::Inval));