diff --git a/Cargo.lock b/Cargo.lock index e8a06b68b..d19911a3f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4890,6 +4890,8 @@ dependencies = [ "time 0.3.20", "tldextract", "toml", + "tracing", + "tracing-subscriber 0.3.16", "unix_mode", "url", "walkdir", diff --git a/lib/api/src/function_env.rs b/lib/api/src/function_env.rs index 2209d57c8..7a4551c6a 100644 --- a/lib/api/src/function_env.rs +++ b/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, } +impl<'a, T> Debug for FunctionEnvMut<'a, T> { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "env_mut") + } +} + impl FunctionEnvMut<'_, T> { /// Returns a reference to the host state in this function environement. pub fn data(&self) -> &T { diff --git a/lib/api/src/ptr.rs b/lib/api/src/ptr.rs index 079b82b7c..206cb8063 100644 --- a/lib/api/src/ptr.rs +++ b/lib/api/src/ptr.rs @@ -278,11 +278,6 @@ impl Eq for WasmPtr {} impl fmt::Debug for WasmPtr { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - write!( - f, - "WasmPtr(offset: {}, pointer: {:#x})", - self.offset.into(), - self.offset.into() - ) + write!(f, "{}(@{})", std::any::type_name::(), self.offset.into()) } } diff --git a/lib/cli/Cargo.toml b/lib/cli/Cargo.toml index bd9555064..16bb64cc4 100644 --- a/lib/cli/Cargo.toml +++ b/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 = [ diff --git a/lib/cli/src/logging.rs b/lib/cli/src/logging.rs index d60a45fbf..887c6a7eb 100644 --- a/lib/cli/src/logging.rs +++ b/lib/cli/src/logging.rs @@ -1,14 +1,44 @@ //! Logging functions for the debug feature. -use crate::utils::wasmer_should_print_color; -use anyhow::Result; -use fern::colors::{Color, ColoredLevelConfig}; -use std::time; - -/// The debug level -pub type DebugLevel = log::LevelFilter; /// 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}; + use std::time; + + /// The debug level + pub type DebugLevel = log::LevelFilter; + let colors_line = ColoredLevelConfig::new() .error(Color::Red) .warn(Color::Yellow) diff --git a/lib/wasi-types/src/wasi/bindings.rs b/lib/wasi-types/src/wasi/bindings.rs index 1f31133b3..5a7778737 100644 --- a/lib/wasi-types/src/wasi/bindings.rs +++ b/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") - .field("code", &(*self as i32)) - .field("name", &self.name()) - .field("message", &self.message()) - .finish() + write!(f, "Errno::{}", &self.name()) } } 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") - .field("code", &(*self as i32)) - .field("name", &self.name()) - .field("message", &self.message()) - .finish() + write!(f, "BusErrno::{}", &self.name()) } } 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 { diff --git a/lib/wasi/Cargo.toml b/lib/wasi/Cargo.toml index 8d9bad051..425e885ca 100644 --- a/lib/wasi/Cargo.toml +++ b/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 } diff --git a/lib/wasi/src/os/task/process.rs b/lib/wasi/src/os/task/process.rs index 3be8e8be8..b2ceb2667 100644 --- a/lib/wasi/src/os/task/process.rs +++ b/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)] diff --git a/lib/wasi/src/os/task/thread.rs b/lib/wasi/src/os/task/thread.rs index bccaafd17..6304f20e7 100644 --- a/lib/wasi/src/os/task/thread.rs +++ b/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 { diff --git a/lib/wasi/src/syscalls/legacy/snapshot0.rs b/lib/wasi/src/syscalls/legacy/snapshot0.rs index 82e81d236..3e1bdd696 100644 --- a/lib/wasi/src/syscalls/legacy/snapshot0.rs +++ b/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, 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, 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, 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, in_: WasmPtr, @@ -157,12 +162,7 @@ pub fn poll_oneoff( let triggered_events = match triggered_events { Ok(a) => a, Err(err) => { - tracing::trace!( - "wasi[{}:{}]::poll_oneoff0 errno={}", - ctx.data().pid(), - ctx.data().tid(), - err - ); + tracing::trace!(err = err as u16); return Ok(err); } }; diff --git a/lib/wasi/src/syscalls/mod.rs b/lib/wasi/src/syscalls/mod.rs index 685be1653..e3a3926a1 100644 --- a/lib/wasi/src/syscalls/mod.rs +++ b/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( 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::(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( mut ctx: FunctionEnvMut<'_, WasiEnv>, @@ -942,15 +943,6 @@ pub(crate) fn rewind( 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))); diff --git a/lib/wasi/src/syscalls/wasi/args_get.rs b/lib/wasi/src/syscalls/wasi/args_get.rs index 9db871a60..ec29be238 100644 --- a/lib/wasi/src/syscalls/wasi/args_get.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, argv: WasmPtr, M>, argv_buf: WasmPtr, ) -> 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( let result = write_buffer_array(&memory, &args, argv, argv_buf); debug!( - "=> args:\n{}", + "args:\n{}", state .args .iter() diff --git a/lib/wasi/src/syscalls/wasi/args_sizes_get.rs b/lib/wasi/src/syscalls/wasi/args_sizes_get.rs index 2d4478e8d..4e60962fc 100644 --- a/lib/wasi/src/syscalls/wasi/args_sizes_get.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, argc: WasmPtr, argv_buf_size: WasmPtr, ) -> 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( 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 } diff --git a/lib/wasi/src/syscalls/wasi/clock_res_get.rs b/lib/wasi/src/syscalls/wasi/clock_res_get.rs index 4fe530bb8..4c24a9916 100644 --- a/lib/wasi/src/syscalls/wasi/clock_res_get.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, clock_id: Snapshot0Clockid, resolution: WasmPtr, ) -> Errno { - trace!( - "wasi[{}:{}]::clock_res_get", - ctx.data().pid(), - ctx.data().tid() - ); let env = ctx.data(); let memory = env.memory_view(&ctx); diff --git a/lib/wasi/src/syscalls/wasi/clock_time_get.rs b/lib/wasi/src/syscalls/wasi/clock_time_get.rs index d3cfb9483..742ea17ad 100644 --- a/lib/wasi/src/syscalls/wasi/clock_time_get.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, clock_id: Snapshot0Clockid, precision: Timestamp, time: WasmPtr, ) -> 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( } }; wasi_try_mem!(time.write(&memory, t_out as Timestamp)); - - /* - trace!( - "time: {} => {}", - wasi_try_mem!(time.deref(&memory).read()), - result - ); - */ Errno::Success } diff --git a/lib/wasi/src/syscalls/wasi/clock_time_set.rs b/lib/wasi/src/syscalls/wasi/clock_time_set.rs index 3ba8f5c21..f6614f22e 100644 --- a/lib/wasi/src/syscalls/wasi/clock_time_set.rs +++ b/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( 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( let mut guard = env.state.clock_offset.lock().unwrap(); guard.insert(clock_id, t_offset); - Errno::Success } diff --git a/lib/wasi/src/syscalls/wasi/environ_get.rs b/lib/wasi/src/syscalls/wasi/environ_get.rs index 13aa158cc..3db40af18 100644 --- a/lib/wasi/src/syscalls/wasi/environ_get.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, environ: WasmPtr, M>, environ_buf: WasmPtr, ) -> 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) } diff --git a/lib/wasi/src/syscalls/wasi/environ_sizes_get.rs b/lib/wasi/src/syscalls/wasi/environ_sizes_get.rs index 42a9649c2..7c9496f5c 100644 --- a/lib/wasi/src/syscalls/wasi/environ_sizes_get.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, environ_count: WasmPtr, environ_buf_size: WasmPtr, ) -> 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( wasi_try_mem!(environ_buf_size.write(env_buf_size)); trace!( - "env_var_count: {}, env_buf_size: {}", - env_var_count, - env_buf_size + %env_var_count, + %env_buf_size ); Errno::Success diff --git a/lib/wasi/src/syscalls/wasi/fd_advise.rs b/lib/wasi/src/syscalls/wasi/fd_advise.rs index dba63f05a..eb2eba940 100644 --- a/lib/wasi/src/syscalls/wasi/fd_advise.rs +++ b/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 diff --git a/lib/wasi/src/syscalls/wasi/fd_allocate.rs b/lib/wasi/src/syscalls/wasi/fd_allocate.rs index 8056d1274..ff44ff212 100644 --- a/lib/wasi/src/syscalls/wasi/fd_allocate.rs +++ b/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 } diff --git a/lib/wasi/src/syscalls/wasi/fd_close.rs b/lib/wasi/src/syscalls/wasi/fd_close.rs index 531e41c13..d5fcaec6e 100644 --- a/lib/wasi/src/syscalls/wasi/fd_close.rs +++ b/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 { - 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)); diff --git a/lib/wasi/src/syscalls/wasi/fd_datasync.rs b/lib/wasi/src/syscalls/wasi/fd_datasync.rs index 698f6d776..cf3704303 100644 --- a/lib/wasi/src/syscalls/wasi/fd_datasync.rs +++ b/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 { - 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)); diff --git a/lib/wasi/src/syscalls/wasi/fd_dup.rs b/lib/wasi/src/syscalls/wasi/fd_dup.rs index 405502efd..deea9f8da 100644 --- a/lib/wasi/src/syscalls/wasi/fd_dup.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, ret_fd: WasmPtr, ) -> 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 diff --git a/lib/wasi/src/syscalls/wasi/fd_event.rs b/lib/wasi/src/syscalls/wasi/fd_event.rs index 2017627b7..69d791bb4 100644 --- a/lib/wasi/src/syscalls/wasi/fd_event.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, initial_val: u64, flags: EventFdFlags, ret_fd: WasmPtr, ) -> 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( .fs .create_fd(rights, rights, Fdflags::empty(), 0, inode)); - trace!( - "wasi[{}:{}]::fd_event - event notifications created (fd={})", - ctx.data().pid(), - ctx.data().tid(), - fd - ); + Span::current().record("ret_fd", fd); wasi_try_mem!(ret_fd.write(&memory, fd)); Errno::Success diff --git a/lib/wasi/src/syscalls/wasi/fd_fdstat_get.rs b/lib/wasi/src/syscalls/wasi/fd_fdstat_get.rs index b337868bb..78d094d17 100644 --- a/lib/wasi/src/syscalls/wasi/fd_fdstat_get.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, buf_ptr: WasmPtr, ) -> 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)); diff --git a/lib/wasi/src/syscalls/wasi/fd_fdstat_set_flags.rs b/lib/wasi/src/syscalls/wasi/fd_fdstat_set_flags.rs index 63d82d8ae..6fb25a9c4 100644 --- a/lib/wasi/src/syscalls/wasi/fd_fdstat_set_flags.rs +++ b/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 { - 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); } } diff --git a/lib/wasi/src/syscalls/wasi/fd_fdstat_set_rights.rs b/lib/wasi/src/syscalls/wasi/fd_fdstat_set_rights.rs index 68bb04adc..194e49bc0 100644 --- a/lib/wasi/src/syscalls/wasi/fd_fdstat_set_rights.rs +++ b/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(); diff --git a/lib/wasi/src/syscalls/wasi/fd_filestat_get.rs b/lib/wasi/src/syscalls/wasi/fd_filestat_get.rs index d55c5b8ac..e1b98f7c3 100644 --- a/lib/wasi/src/syscalls/wasi/fd_filestat_get.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, @@ -30,11 +31,6 @@ pub(crate) fn fd_filestat_get_internal( fd: WasiFd, buf: WasmPtr, ) -> 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)); diff --git a/lib/wasi/src/syscalls/wasi/fd_filestat_set_size.rs b/lib/wasi/src/syscalls/wasi/fd_filestat_set_size.rs index 01024228b..30792e1f2 100644 --- a/lib/wasi/src/syscalls/wasi/fd_filestat_set_size.rs +++ b/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)); diff --git a/lib/wasi/src/syscalls/wasi/fd_filestat_set_times.rs b/lib/wasi/src/syscalls/wasi/fd_filestat_set_times.rs index 2bb32fa28..e46663afd 100644 --- a/lib/wasi/src/syscalls/wasi/fd_filestat_set_times.rs +++ b/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)); diff --git a/lib/wasi/src/syscalls/wasi/fd_prestat_dir_name.rs b/lib/wasi/src/syscalls/wasi/fd_prestat_dir_name.rs index 70b5b3506..c14314bc3 100644 --- a/lib/wasi/src/syscalls/wasi/fd_prestat_dir_name.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, path: WasmPtr, 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)); diff --git a/lib/wasi/src/syscalls/wasi/fd_prestat_get.rs b/lib/wasi/src/syscalls/wasi/fd_prestat_get.rs index 918892df7..1b7ee155e 100644 --- a/lib/wasi/src/syscalls/wasi/fd_prestat_get.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, buf: WasmPtr, ) -> 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!( - prestat_ptr.write(wasi_try!(state.fs.prestat_fd(fd).map_err(|code| { - debug!("fd_prestat_get failed (fd={}) - errno={}", fd, code); - code - }))) - ); + wasi_try_mem!(prestat_ptr.write(wasi_try!(state.fs.prestat_fd(fd)))); Errno::Success } diff --git a/lib/wasi/src/syscalls/wasi/fd_read.rs b/lib/wasi/src/syscalls/wasi/fd_read.rs index 91cf7eeae..9beff33fc 100644 --- a/lib/wasi/src/syscalls/wasi/fd_read.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, @@ -41,29 +42,13 @@ pub fn fd_read( let mut ret = Errno::Success; let bytes_read = match res { - Ok(bytes_read) => { - trace!( - %fd, - %bytes_read, - "wasi[{}:{}]::fd_read", - ctx.data().pid(), - ctx.data().tid(), - ); - bytes_read - } + Ok(bytes_read) => 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( /// Output: /// - `size_t nread` /// The number of bytes read +#[instrument(level = "trace", skip_all, fields(fd, offset, nread), ret, err)] pub fn fd_pread( mut ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, @@ -108,33 +94,13 @@ pub fn fd_pread( let mut ret = Errno::Success; let bytes_read = match res { - Ok(bytes_read) => { - trace!( - %fd, - %offset, - %bytes_read, - "wasi[{}:{}]::fd_pread - {:?}", - ctx.data().pid(), - ctx.data().tid(), - ret - ); - bytes_read - } + Ok(bytes_read) => 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)); diff --git a/lib/wasi/src/syscalls/wasi/fd_readdir.rs b/lib/wasi/src/syscalls/wasi/fd_readdir.rs index 761de3294..e5f21330b 100644 --- a/lib/wasi/src/syscalls/wasi/fd_readdir.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, @@ -24,11 +25,6 @@ pub fn fd_readdir( cookie: Dircookie, bufused: WasmPtr, ) -> 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( 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( .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( 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( 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, diff --git a/lib/wasi/src/syscalls/wasi/fd_renumber.rs b/lib/wasi/src/syscalls/wasi/fd_renumber.rs index 7b4e1ea27..fac8a574c 100644 --- a/lib/wasi/src/syscalls/wasi/fd_renumber.rs +++ b/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; } diff --git a/lib/wasi/src/syscalls/wasi/fd_seek.rs b/lib/wasi/src/syscalls/wasi/fd_seek.rs index c91d54c79..0d146ef92 100644 --- a/lib/wasi/src/syscalls/wasi/fd_seek.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, @@ -20,15 +21,6 @@ pub fn fd_seek( whence: Whence, newoffset: WasmPtr, ) -> Result { - 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( wasi_try_mem_ok!(new_offset_ref.write(new_offset)); trace!( - "wasi[{}:{}]::fd_seek: fd={}, new_offset={}", - ctx.data().pid(), - ctx.data().tid(), - fd, - new_offset, + %new_offset, ); Ok(Errno::Success) diff --git a/lib/wasi/src/syscalls/wasi/fd_sync.rs b/lib/wasi/src/syscalls/wasi/fd_sync.rs index e5ba7cfea..bcfaf37c8 100644 --- a/lib/wasi/src/syscalls/wasi/fd_sync.rs +++ b/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 { - 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)); diff --git a/lib/wasi/src/syscalls/wasi/fd_tell.rs b/lib/wasi/src/syscalls/wasi/fd_tell.rs index cc43ff4fa..223518426 100644 --- a/lib/wasi/src/syscalls/wasi/fd_tell.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, offset: WasmPtr, ) -> 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( 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 } diff --git a/lib/wasi/src/syscalls/wasi/fd_write.rs b/lib/wasi/src/syscalls/wasi/fd_write.rs index bda5bf0d1..295b6a0c8 100644 --- a/lib/wasi/src/syscalls/wasi/fd_write.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, @@ -22,13 +23,6 @@ pub fn fd_write( iovs_len: M::Offset, nwritten: WasmPtr, ) -> Result { - 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( /// Output: /// - `u32 *nwritten` /// Number of bytes written +#[instrument(level = "trace", skip_all, fields(fd, offset, nwritten = field::Empty), ret, err)] pub fn fd_pwrite( mut ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, @@ -63,14 +58,6 @@ pub fn fd_pwrite( offset: Filesize, nwritten: WasmPtr, ) -> Result { - trace!( - "wasi[{}:{}]::fd_pwrite (fd={}, offset={})", - ctx.data().pid(), - ctx.data().tid(), - fd, - offset, - ); - fd_write_internal::(ctx, fd, iovs, iovs_len, offset as usize, nwritten, false) } @@ -260,6 +247,7 @@ fn fd_write_internal( } bytes_written }; + Span::current().record("nwritten", bytes_written); let memory = env.memory_view(&ctx); let nwritten_ref = nwritten.deref(&memory); diff --git a/lib/wasi/src/syscalls/wasi/mod.rs b/lib/wasi/src/syscalls/wasi/mod.rs index 8247d92c2..ebf619eca 100644 --- a/lib/wasi/src/syscalls/wasi/mod.rs +++ b/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}; diff --git a/lib/wasi/src/syscalls/wasi/path_create_directory.rs b/lib/wasi/src/syscalls/wasi/path_create_directory.rs index 7d8fb47a3..87662fadc 100644 --- a/lib/wasi/src/syscalls/wasi/path_create_directory.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, path: WasmPtr, 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( 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={}))", - ctx.data().pid(), - ctx.data().tid(), - path_string + %path_string ); } @@ -66,12 +59,8 @@ pub fn path_create_directory( 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() { diff --git a/lib/wasi/src/syscalls/wasi/path_filestat_get.rs b/lib/wasi/src/syscalls/wasi/path_filestat_get.rs index e3f25eb53..ea1fa4036 100644 --- a/lib/wasi/src/syscalls/wasi/path_filestat_get.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, @@ -27,24 +28,12 @@ pub fn path_filestat_get( 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, diff --git a/lib/wasi/src/syscalls/wasi/path_filestat_set_times.rs b/lib/wasi/src/syscalls/wasi/path_filestat_set_times.rs index 839162c85..3c2dc9145 100644 --- a/lib/wasi/src/syscalls/wasi/path_filestat_set_times.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, @@ -28,11 +29,6 @@ pub fn path_filestat_set_times( 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( } 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={}))", - ctx.data().pid(), - ctx.data().tid(), - path_string + %path_string ); } diff --git a/lib/wasi/src/syscalls/wasi/path_link.rs b/lib/wasi/src/syscalls/wasi/path_link.rs index 71a4c4846..f60187e0a 100644 --- a/lib/wasi/src/syscalls/wasi/path_link.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, old_fd: WasiFd, @@ -28,20 +29,17 @@ pub fn path_link( new_path: WasmPtr, 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) diff --git a/lib/wasi/src/syscalls/wasi/path_open.rs b/lib/wasi/src/syscalls/wasi/path_open.rs index 1afd852d2..19d505af8 100644 --- a/lib/wasi/src/syscalls/wasi/path_open.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, dirfd: WasiFd, @@ -37,9 +38,8 @@ pub fn path_open( fs_flags: Fdflags, fd: WasmPtr, ) -> 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( } 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={}))", - ctx.data().pid(), - ctx.data().tid(), - path_string + %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( // nothing bad happens let dup_fd = wasi_try!(state.fs.clone_fd(fd)); trace!( - "wasi[{}:{}]::path_open [special_fd] (dup_fd: {}->{})", - ctx.data().pid(), - ctx.data().tid(), - fd, - dup_fd + %dup_fd ); // some special files will return a constant FD rather than @@ -237,12 +230,10 @@ pub fn path_open( 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( open_flags |= Fd::TRUNCATE; } - Some(wasi_try!(open_options.open(&new_file_host_path).map_err( - |e| { - debug!("Error opening file {}", e); - fs_error_into_wasi_err(e) - } - ))) + Some(wasi_try!(open_options + .open(&new_file_host_path) + .map_err(|e| { fs_error_into_wasi_err(e) }))) }; let new_inode = { @@ -334,13 +322,8 @@ pub fn path_open( inode )); - wasi_try_mem!(fd_ref.write(out_fd)); - debug!( - "wasi[{}:{}]::path_open returning fd {}", - ctx.data().pid(), - ctx.data().tid(), - out_fd - ); + Span::current().record("ret_fd", out_fd); + wasi_try_mem!(fd_ref.write(out_fd)); Errno::Success } diff --git a/lib/wasi/src/syscalls/wasi/path_readlink.rs b/lib/wasi/src/syscalls/wasi/path_readlink.rs index fe5031e60..60067c731 100644 --- a/lib/wasi/src/syscalls/wasi/path_readlink.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, dir_fd: WasiFd, @@ -26,11 +27,6 @@ pub fn path_readlink( buf_len: M::Offset, buf_used: WasmPtr, ) -> 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( 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={}))", - ctx.data().pid(), - ctx.data().tid(), - path_str + %path_str ); } @@ -57,7 +51,6 @@ pub fn path_readlink( 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 { diff --git a/lib/wasi/src/syscalls/wasi/path_remove_directory.rs b/lib/wasi/src/syscalls/wasi/path_remove_directory.rs index a940c2d11..71ab4bc3a 100644 --- a/lib/wasi/src/syscalls/wasi/path_remove_directory.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, @@ -9,25 +10,18 @@ pub fn path_remove_directory( 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={}))", - ctx.data().pid(), - ctx.data().tid(), - path_str + %path_str ); } diff --git a/lib/wasi/src/syscalls/wasi/path_rename.rs b/lib/wasi/src/syscalls/wasi/path_rename.rs index 6225f062e..3eb34a730 100644 --- a/lib/wasi/src/syscalls/wasi/path_rename.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, old_fd: WasiFd, @@ -25,19 +26,16 @@ pub fn path_rename( new_path: WasmPtr, 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( 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( 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( 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" ); } } diff --git a/lib/wasi/src/syscalls/wasi/path_symlink.rs b/lib/wasi/src/syscalls/wasi/path_symlink.rs index dbd2148fa..999b7250b 100644 --- a/lib/wasi/src/syscalls/wasi/path_symlink.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, old_path: WasmPtr, @@ -22,15 +23,12 @@ pub fn path_symlink( new_path: WasmPtr, 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( 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, diff --git a/lib/wasi/src/syscalls/wasi/path_unlink_file.rs b/lib/wasi/src/syscalls/wasi/path_unlink_file.rs index 10d43d2bb..54a55713e 100644 --- a/lib/wasi/src/syscalls/wasi/path_unlink_file.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, fd: WasiFd, path: WasmPtr, 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( 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)); diff --git a/lib/wasi/src/syscalls/wasi/poll_oneoff.rs b/lib/wasi/src/syscalls/wasi/poll_oneoff.rs index a642080f0..6285d56c9 100644 --- a/lib/wasi/src/syscalls/wasi/poll_oneoff.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, in_: WasmPtr, @@ -49,12 +50,6 @@ pub fn poll_oneoff( 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!( - "wasi[{}:{}]::poll_oneoff triggered_fd (fd={}, userdata={}, type={:?})", - pid, - tid, - fd, - evt.userdata, - evt.type_, - ); + tracing::trace!(fd, userdata = evt.userdata, ty = evt.type_ as u8,); 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!( - "wasi[{}:{}]::poll_oneoff wait_for_timeout={}", - pid, - tid, - time_to_sleep.as_millis() - ); + Span::current().record("timeout_ns", 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!( - "wasi[{}:{}]::poll_oneoff seen={}", - ctx.data().pid(), - ctx.data().tid(), - evts.len() - ); + Span::current().record("seen", 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!( - "wasi[{}:{}]::poll_oneoff triggered_timeout (without any clock subscriptions)", - pid, - tid - ); + tracing::warn!("triggered_timeout (without any clock subscriptions)",); } 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!( - "wasi[{}:{}]::poll_oneoff triggered_clock id={:?} (userdata={})", - pid, - tid, - clock_info.clock_id, - evt.userdata, + Span::current().record( + "seen", + &format!( + "clock(id={},userdata={})", + clock_info.clock_id as u32, evt.userdata + ), ); evts.push(evt); } diff --git a/lib/wasi/src/syscalls/wasi/proc_exit.rs b/lib/wasi/src/syscalls/wasi/proc_exit.rs index 83869eacb..ac1d5c95c 100644 --- a/lib/wasi/src/syscalls/wasi/proc_exit.rs +++ b/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( 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( // 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( 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)); } diff --git a/lib/wasi/src/syscalls/wasi/proc_raise.rs b/lib/wasi/src/syscalls/wasi/proc_raise.rs index c265ed963..b21850f54 100644 --- a/lib/wasi/src/syscalls/wasi/proc_raise.rs +++ b/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 { - 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 { - debug!( - "wasi[{}:{}]::proc_raise_interval (sig={:?})", - ctx.data().pid(), - ctx.data().tid(), - sig - ); let env = ctx.data(); let interval = match interval { 0 => None, diff --git a/lib/wasi/src/syscalls/wasi/random_get.rs b/lib/wasi/src/syscalls/wasi/random_get.rs index 73c5ab76d..ea633aca0 100644 --- a/lib/wasi/src/syscalls/wasi/random_get.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, buf: WasmPtr, 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(); diff --git a/lib/wasi/src/syscalls/wasix/callback_reactor.rs b/lib/wasi/src/syscalls/wasix/callback_reactor.rs index c5659c097..57f175569 100644 --- a/lib/wasi/src/syscalls/wasix/callback_reactor.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, name: WasmPtr, @@ -15,12 +16,7 @@ pub fn callback_reactor( let env = ctx.data(); let memory = env.memory_view(&ctx); let name = unsafe { name.read_utf8_string(&memory, name_len)? }; - debug!( - "wasi[{}:{}]::callback_reactor (name={})", - ctx.data().pid(), - ctx.data().tid(), - name - ); + Span::current().record("name", name.as_str()); let funct = env .inner() @@ -28,6 +24,7 @@ pub fn callback_reactor( .exports .get_typed_function(&ctx, &name) .ok(); + Span::current().record("funct_is_some", funct.is_some()); ctx.data_mut().inner_mut().react = funct; Ok(()) diff --git a/lib/wasi/src/syscalls/wasix/callback_signal.rs b/lib/wasi/src/syscalls/wasix/callback_signal.rs index 51bdb788a..f18ea8b56 100644 --- a/lib/wasi/src/syscalls/wasix/callback_signal.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, name: WasmPtr, @@ -26,6 +27,7 @@ pub fn callback_signal( } } }; + Span::current().record("name", name.as_str()); let funct = env .inner() @@ -33,13 +35,7 @@ pub fn callback_signal( .exports .get_typed_function(&ctx, &name) .ok(); - trace!( - "wasi[{}:{}]::callback_signal (name={}, found={})", - ctx.data().pid(), - ctx.data().tid(), - name, - funct.is_some() - ); + Span::current().record("funct_is_some", funct.is_some()); { let inner = ctx.data_mut().inner_mut(); diff --git a/lib/wasi/src/syscalls/wasix/callback_thread.rs b/lib/wasi/src/syscalls/wasix/callback_thread.rs index 60a96abde..89b23bd18 100644 --- a/lib/wasi/src/syscalls/wasix/callback_thread.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, name: WasmPtr, @@ -14,13 +15,9 @@ pub fn callback_thread( ) -> Result<(), MemoryAccessError> { let env = ctx.data(); let memory = env.memory_view(&ctx); + let name = unsafe { name.read_utf8_string(&memory, name_len)? }; - debug!( - "wasi[{}:{}]::callback_spawn (name={})", - ctx.data().pid(), - ctx.data().tid(), - name - ); + Span::current().record("name", name.as_str()); let funct = env .inner() @@ -28,6 +25,7 @@ pub fn callback_thread( .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(()) diff --git a/lib/wasi/src/syscalls/wasix/callback_thread_local_destroy.rs b/lib/wasi/src/syscalls/wasix/callback_thread_local_destroy.rs index 8fa9127f2..9e39550b3 100644 --- a/lib/wasi/src/syscalls/wasix/callback_thread_local_destroy.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, name: WasmPtr, @@ -14,13 +15,9 @@ pub fn callback_thread_local_destroy( ) -> Result<(), MemoryAccessError> { let env = ctx.data(); let memory = env.memory_view(&ctx); + let name = unsafe { name.read_utf8_string(&memory, name_len)? }; - debug!( - "wasi[{}:{}]::callback_thread_local_destroy (name={})", - ctx.data().pid(), - ctx.data().tid(), - name - ); + Span::current().record("name", name.as_str()); let funct = env .inner() @@ -28,6 +25,7 @@ pub fn callback_thread_local_destroy( .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(()) diff --git a/lib/wasi/src/syscalls/wasix/chdir.rs b/lib/wasi/src/syscalls/wasix/chdir.rs index ea7bbd364..58e66963f 100644 --- a/lib/wasi/src/syscalls/wasix/chdir.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, path: WasmPtr, @@ -11,12 +12,7 @@ pub fn chdir( 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!( - "wasi[{}:{}]::chdir [{}]", - ctx.data().pid(), - ctx.data().tid(), - path - ); + Span::current().record("path", path.as_str()); // Check if the directory exists if state.fs.root_fs.read_dir(Path::new(path.as_str())).is_err() { diff --git a/lib/wasi/src/syscalls/wasix/fd_pipe.rs b/lib/wasi/src/syscalls/wasix/fd_pipe.rs index ed3200d65..2f6e4a8d5 100644 --- a/lib/wasi/src/syscalls/wasix/fd_pipe.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, ro_fd1: WasmPtr, ro_fd2: WasmPtr, ) -> 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( let fd2 = wasi_try!(state .fs .create_fd(rights, rights, Fdflags::empty(), 0, inode2)); - trace!( - "wasi[{}:{}]::fd_pipe (fd1={}, fd2={})", - ctx.data().pid(), - ctx.data().tid(), - fd1, - fd2 - ); + Span::current().record("fd1", fd1).record("fd2", fd2); wasi_try_mem!(ro_fd1.write(&memory, fd1)); wasi_try_mem!(ro_fd2.write(&memory, fd2)); diff --git a/lib/wasi/src/syscalls/wasix/futex_wait.rs b/lib/wasi/src/syscalls/wasix/futex_wait.rs index 41dfd83a7..dc806195f 100644 --- a/lib/wasi/src/syscalls/wasix/futex_wait.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, futex_ptr: WasmPtr, @@ -85,17 +86,11 @@ pub fn futex_wait( OptionTag::Some => Some(Duration::from_nanos(timeout.u as u64)), _ => None, }; - - trace!( - "wasi[{}:{}]::futex_wait(offset={}, timeout={:?})", - ctx.data().pid(), - ctx.data().tid(), - futex_ptr.offset(), - timeout - ); + Span::current().record("timeout", &format!("{:?}", 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( } 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)); diff --git a/lib/wasi/src/syscalls/wasix/futex_wake.rs b/lib/wasi/src/syscalls/wasix/futex_wake.rs index aa1e1a091..6238e0aaf 100644 --- a/lib/wasi/src/syscalls/wasix/futex_wake.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, futex_ptr: WasmPtr, @@ -18,8 +19,9 @@ pub fn futex_wake( 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( false } }; - if 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() - ); - } + Span::current().record("woken", woken); let woken = match woken { false => Bool::False, diff --git a/lib/wasi/src/syscalls/wasix/futex_wake_all.rs b/lib/wasi/src/syscalls/wasix/futex_wake_all.rs index 10cb78035..a0990aaf4 100644 --- a/lib/wasi/src/syscalls/wasix/futex_wake_all.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, futex_ptr: WasmPtr, @@ -16,8 +17,9 @@ pub fn futex_wake_all( 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( false } }; - if 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() - ); - } + Span::current().record("woken", woken); let woken = match woken { false => Bool::False, diff --git a/lib/wasi/src/syscalls/wasix/getcwd.rs b/lib/wasi/src/syscalls/wasix/getcwd.rs index 85404d7f4..59afb402a 100644 --- a/lib/wasi/src/syscalls/wasix/getcwd.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, path: WasmPtr, path_len: WasmPtr, ) -> 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!( - "wasi[{}:{}]::getcwd(current_dir={})", - ctx.data().pid(), - ctx.data().tid(), - cur_dir - ); + Span::current().record("path", cur_dir.as_str()); 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::(cur_dir.len())))); diff --git a/lib/wasi/src/syscalls/wasix/mod.rs b/lib/wasi/src/syscalls/wasix/mod.rs index f0a8e23aa..5079af351 100644 --- a/lib/wasi/src/syscalls/wasix/mod.rs +++ b/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}; diff --git a/lib/wasi/src/syscalls/wasix/port_addr_add.rs b/lib/wasi/src/syscalls/wasix/port_addr_add.rs index fb8069d96..5a87a5b4a 100644 --- a/lib/wasi/src/syscalls/wasix/port_addr_add.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, ip: WasmPtr<__wasi_cidr_t, M>, ) -> Result { - 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) diff --git a/lib/wasi/src/syscalls/wasix/port_addr_clear.rs b/lib/wasi/src/syscalls/wasix/port_addr_clear.rs index 01a0192dc..3129d62c0 100644 --- a/lib/wasi/src/syscalls/wasix/port_addr_clear.rs +++ b/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 { - 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 { diff --git a/lib/wasi/src/syscalls/wasix/port_addr_list.rs b/lib/wasi/src/syscalls/wasix/port_addr_list.rs index 6edd4dc09..33637e776 100644 --- a/lib/wasi/src/syscalls/wasix/port_addr_list.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, addrs_ptr: WasmPtr<__wasi_cidr_t, M>, naddrs_ptr: WasmPtr, ) -> Result { - 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( })?); 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)); diff --git a/lib/wasi/src/syscalls/wasix/port_addr_remove.rs b/lib/wasi/src/syscalls/wasix/port_addr_remove.rs index a3cb57023..085480482 100644 --- a/lib/wasi/src/syscalls/wasix/port_addr_remove.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, ip: WasmPtr<__wasi_addr_t, M>, ) -> Result { - 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) diff --git a/lib/wasi/src/syscalls/wasix/port_bridge.rs b/lib/wasi/src/syscalls/wasix/port_bridge.rs index 448b31c96..8d893c72d 100644 --- a/lib/wasi/src/syscalls/wasix/port_bridge.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, network: WasmPtr, @@ -17,14 +18,12 @@ pub fn port_bridge( token_len: M::Offset, security: Streamsecurity, ) -> Result { - 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, diff --git a/lib/wasi/src/syscalls/wasix/port_dhcp_acquire.rs b/lib/wasi/src/syscalls/wasix/port_dhcp_acquire.rs index 641ecabb7..38fcf3b01 100644 --- a/lib/wasi/src/syscalls/wasix/port_dhcp_acquire.rs +++ b/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 { - 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(); diff --git a/lib/wasi/src/syscalls/wasix/port_gateway_set.rs b/lib/wasi/src/syscalls/wasix/port_gateway_set.rs index 2f38afbe6..29bdee1a8 100644 --- a/lib/wasi/src/syscalls/wasix/port_gateway_set.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, ip: WasmPtr<__wasi_addr_t, M>, ) -> Result { - 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 { diff --git a/lib/wasi/src/syscalls/wasix/port_mac.rs b/lib/wasi/src/syscalls/wasix/port_mac.rs index 3b8db53a8..d46751114 100644 --- a/lib/wasi/src/syscalls/wasix/port_mac.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, ret_mac: WasmPtr<__wasi_hardwareaddress_t, M>, ) -> Result { - 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( 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) diff --git a/lib/wasi/src/syscalls/wasix/port_route_add.rs b/lib/wasi/src/syscalls/wasix/port_route_add.rs index 53d37c257..e8180ec75 100644 --- a/lib/wasi/src/syscalls/wasix/port_route_add.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, cidr: WasmPtr<__wasi_cidr_t, M>, @@ -10,15 +11,15 @@ pub fn port_route_add( preferred_until: WasmPtr, expires_at: WasmPtr, ) -> Result { - 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, diff --git a/lib/wasi/src/syscalls/wasix/port_route_clear.rs b/lib/wasi/src/syscalls/wasix/port_route_clear.rs index 01228ded1..f006b07b9 100644 --- a/lib/wasi/src/syscalls/wasix/port_route_clear.rs +++ b/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 { - 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 { diff --git a/lib/wasi/src/syscalls/wasix/port_route_list.rs b/lib/wasi/src/syscalls/wasix/port_route_list.rs index 2bb31ff62..eec6d1184 100644 --- a/lib/wasi/src/syscalls/wasix/port_route_list.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, routes_ptr: WasmPtr, nroutes_ptr: WasmPtr, ) -> Result { - 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::(max_routes)))); @@ -33,6 +30,8 @@ pub fn port_route_list( 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); diff --git a/lib/wasi/src/syscalls/wasix/port_route_remove.rs b/lib/wasi/src/syscalls/wasix/port_route_remove.rs index c0a73e24f..942c8d416 100644 --- a/lib/wasi/src/syscalls/wasix/port_route_remove.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, ip: WasmPtr<__wasi_addr_t, M>, ) -> Result { - 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 { diff --git a/lib/wasi/src/syscalls/wasix/port_unbridge.rs b/lib/wasi/src/syscalls/wasix/port_unbridge.rs index 488b46b8b..5d2120fa7 100644 --- a/lib/wasi/src/syscalls/wasix/port_unbridge.rs +++ b/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 { - 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 { diff --git a/lib/wasi/src/syscalls/wasix/proc_exec.rs b/lib/wasi/src/syscalls/wasix/proc_exec.rs index 704bb8e1e..e8a16f2a6 100644 --- a/lib/wasi/src/syscalls/wasix/proc_exec.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, name: WasmPtr, @@ -27,13 +28,7 @@ pub fn proc_exec( warn!("failed to execve as the name could not be read - {}", err); WasiError::Exit(Errno::Fault as ExitCode) })?; - trace!( - "wasi[{}:{}]::proc_exec (name={})", - ctx.data().pid(), - ctx.data().tid(), - name - ); - + Span::current().record("name", name.as_str()); 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( // 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( Ok(a) => Some(a), Err(err) => { if err != VirtualBusError::NotFound { - error!( - "wasi[{}:{}]::proc_exec - builtin failed - {}", - ctx.data().pid(), - ctx.data().tid(), - err - ); + error!("builtin failed - {}", err); } let new_store = new_store.take().unwrap(); @@ -149,21 +134,11 @@ pub fn proc_exec( // exit code can be processed let process = match process { Some(a) => { - trace!( - "wasi[{}:{}]::spawned sub-process (pid={})", - ctx.data().pid(), - ctx.data().tid(), - child_pid.raw() - ); + trace!("spawned sub-process (pid={})", child_pid.raw()); a } None => { - debug!( - "wasi[{}:{}]::process failed with (err={})", - ctx.data().pid(), - ctx.data().tid(), - err_exit_code - ); + debug!("process failed with (err={})", err_exit_code); OwnedTaskStatus::new(TaskStatus::Finished(Ok(err_exit_code))).handle() } }; @@ -185,7 +160,11 @@ pub fn proc_exec( // 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( 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( Ok(a) => Ok(Ok(a)), Err(err) => { if err != VirtualBusError::NotFound { - error!( - "wasi[{}:{}]::proc_exec - builtin failed - {}", - ctx.data().pid(), - ctx.data().tid(), - err - ); + error!("builtin failed - {}", err); } let new_store = new_store.take().unwrap(); diff --git a/lib/wasi/src/syscalls/wasix/proc_fork.rs b/lib/wasi/src/syscalls/wasix/proc_fork.rs index e0b64cb14..3078674fd 100644 --- a/lib/wasi/src/syscalls/wasix/proc_fork.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, mut copy_memory: Bool, @@ -15,39 +16,10 @@ pub fn proc_fork( 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::(&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!( - "wasi[{}:{}]::proc_{} - capturing", - ctx.data().pid(), - ctx.data().tid(), - fork_op - ); + trace!("capturing",); // 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( let (mut child_env, mut child_handle) = match ctx.data().fork() { Ok(p) => p, Err(err) => { - debug!( - pid=%ctx.data().pid(), - tid=%ctx.data().tid(), - "could not fork process: {err}" - ); + debug!("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( ) { Errno::Success => OnCalledAction::InvokeAgain, err => { - warn!( - "{} failed - could not rewind the stack - errno={}", - fork_op, err - ); + warn!("failed - could not rewind the stack - errno={}", err); OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32))) } } @@ -135,6 +100,13 @@ pub fn proc_fork( // Perform the unwind action unwind::(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( let fork_memory: VMMemory = match env .memory() .try_clone(&ctx) - .ok_or_else(|| { - 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()) - }) + .ok_or_else(|| 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 - {}", - ctx.data().pid(), - ctx.data().tid(), - fork_op, - err + %err ); return OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32))); } @@ -208,16 +168,13 @@ pub fn proc_fork( import_object.define("env", "memory", memory.clone()); memory } else { - error!( - "wasi[{}:{}]::wasm instantiate failed - no memory supplied", - pid, tid - ); + error!("wasm instantiate failed - no memory supplied",); 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( // Rewind the stack and carry on { - trace!( - "wasi[{}:{}]::{}: rewinding child", - ctx.data(&store).pid(), - ctx.data(&store).tid(), - fork_op - ); + trace!("rewinding child"); let ctx = ctx.env.clone().into_mut(&mut store); match rewind::( ctx, @@ -245,7 +197,10 @@ pub fn proc_fork( ) { 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( // Invoke the start function let mut ret = Errno::Success; if ctx.data(&store).thread.is_main() { - trace!( - "wasi[{}:{}]::{}: re-invoking main", - ctx.data(&store).pid(), - ctx.data(&store).tid(), - fork_op - ); + trace!("re-invoking main"); let start = ctx.data(&store).inner().start.clone().unwrap(); start.call(&mut store); } else { - trace!( - "wasi[{}:{}]::{}: re-invoking thread_spawn", - ctx.data(&store).pid(), - ctx.data(&store).tid(), - fork_op - ); + trace!("re-invoking thread_spawn"); let start = ctx.data(&store).inner().thread_spawn.clone().unwrap(); start.call(&mut store, 0, 0); } - trace!( - "wasi[{}:{}]::proc_{} - child exited (code = {})", - ctx.data(&store).pid(), - ctx.data(&store).tid(), - fork_op, - ret - ); + trace!("child exited (code = {})", ret); // Clean up the environment ctx.cleanup((&mut store), Some(ret as ExitCode)); @@ -293,9 +232,7 @@ pub fn proc_fork( .task_wasm(Box::new(task), store, module, spawn_type) .map_err(|err| { warn!( - "wasi[{}:{}]::failed to fork as the process could not be spawned - {}", - ctx.data().pid(), - ctx.data().tid(), + "failed to fork as the process could not be spawned - {}", err ); err @@ -308,12 +245,7 @@ pub fn proc_fork( let process = OwnedTaskStatus::default(); { - trace!( - "wasi[{}:{}]::spawned sub-process (pid={})", - ctx.data().pid(), - ctx.data().tid(), - child_pid.raw() - ); + trace!("spawned sub-process (pid={})", 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( // 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( 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( ) { Errno::Success => OnCalledAction::InvokeAgain, err => { - warn!( - "{} failed - could not rewind the stack - errno={}", - fork_op, err - ); + warn!("failed - could not rewind the stack - errno={}", err); OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32))) } } diff --git a/lib/wasi/src/syscalls/wasix/proc_id.rs b/lib/wasi/src/syscalls/wasix/proc_id.rs index ac24f8a50..2a84c5215 100644 --- a/lib/wasi/src/syscalls/wasix/proc_id.rs +++ b/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(ctx: FunctionEnvMut<'_, WasiEnv>, ret_pid: WasmPtr) -> 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 } diff --git a/lib/wasi/src/syscalls/wasix/proc_join.rs b/lib/wasi/src/syscalls/wasix/proc_join.rs index 4dc8c5dcf..36bac1716 100644 --- a/lib/wasi/src/syscalls/wasix/proc_join.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, pid_ptr: WasmPtr, @@ -17,12 +18,7 @@ pub fn proc_join( let env = ctx.data(); let memory = env.memory_view(&ctx); let pid = wasi_try_mem_ok!(pid_ptr.read(&memory)); - trace!( - "wasi[{}:{}]::proc_join (pid={})", - ctx.data().pid(), - ctx.data().tid(), - pid - ); + Span::current().record("filter_pid", 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( ) .map_err(|err| { trace!( - "wasi[{}:{}]::child join failed (pid={}) - {}", - ctx.data().pid(), - ctx.data().tid(), - pid, - err + %pid, + %err ); err })?); return match child_exit { Some((pid, exit_code)) => { - trace!( - "wasi[{}:{}]::child ({}) exited with {}", - ctx.data().pid(), - ctx.data().tid(), - pid, - exit_code - ); + Span::current() + .record("ret_pid", pid.raw()) + .record("exit_code", 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( 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( }) .map_err(|err| { trace!( - "wasi[{}:{}]::child join failed (pid={}) - {}", - ctx.data().pid(), - ctx.data().tid(), - pid, - err + %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( return Ok(Errno::Success); } - debug!( - "process already terminated or not registered (pid={})", - pid.raw() - ); + Span::current().record("ret_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)); diff --git a/lib/wasi/src/syscalls/wasix/proc_parent.rs b/lib/wasi/src/syscalls/wasix/proc_parent.rs index 032dc1228..1d5e5e5fa 100644 --- a/lib/wasi/src/syscalls/wasix/proc_parent.rs +++ b/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( ctx: FunctionEnvMut<'_, WasiEnv>, pid: Pid, ret_parent: WasmPtr, ) -> 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 { diff --git a/lib/wasi/src/syscalls/wasix/proc_signal.rs b/lib/wasi/src/syscalls/wasix/proc_signal.rs index 3e2d1c83a..8067b8118 100644 --- a/lib/wasi/src/syscalls/wasix/proc_signal.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, pid: Pid, sig: Signal, ) -> Result { - 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) diff --git a/lib/wasi/src/syscalls/wasix/proc_spawn.rs b/lib/wasi/src/syscalls/wasix/proc_spawn.rs index dfaecaf37..b6ce12fad 100644 --- a/lib/wasi/src/syscalls/wasix/proc_spawn.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, name: WasmPtr, @@ -45,19 +46,13 @@ pub fn proc_spawn( 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={})", - ctx.data().pid(), - ctx.data().tid(), - name - ); + + Span::current() + .record("name", name.as_str()) + .record("working_dir", working_dir.as_str()); if chroot == Bool::True { - warn!( - "wasi[{}:{}]::chroot is not currently supported", - ctx.data().pid(), - ctx.data().tid() - ); + warn!("chroot is not currently supported",); 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 [{}]", - ctx.data().pid(), - ctx.data().tid(), + "preopens are not yet supported for spawned processes [{}]", 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!( - "wasi[{}:{}]::fd_pipe (fd1={}, fd2={})", - ctx.data().pid(), - ctx.data().tid(), - pipe, - fd - ); + trace!("fd_pipe (fd1={}, fd2={})", 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!( - "wasi[{}:{}]::proc_spawn - builtin failed - {}", - ctx.data().pid(), - ctx.data().tid(), - err - ); + error!("builtin failed - {}", err); } // Now we actually spawn the process let child_work = diff --git a/lib/wasi/src/syscalls/wasix/resolve.rs b/lib/wasi/src/syscalls/wasix/resolve.rs index 8de344ec4..9eab1e522 100644 --- a/lib/wasi/src/syscalls/wasix/resolve.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, host: WasmPtr, @@ -34,13 +35,7 @@ pub fn resolve( let memory = env.memory_view(&ctx); unsafe { get_input_str_ok!(&memory, host, host_len) } }; - - debug!( - "wasi[{}:{}]::resolve (host={})", - ctx.data().pid(), - ctx.data().tid(), - host_str - ); + Span::current().record("host", host_str.as_str()); let port = if port > 0 { Some(port) } else { None }; diff --git a/lib/wasi/src/syscalls/wasix/sched_yield.rs b/lib/wasi/src/syscalls/wasix/sched_yield.rs index 6c07db5bd..9ae99a0a4 100644 --- a/lib/wasi/src/syscalls/wasix/sched_yield.rs +++ b/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 { //trace!("wasi[{}:{}]::sched_yield", ctx.data().pid(), ctx.data().tid()); thread_sleep_internal(ctx, 0) diff --git a/lib/wasi/src/syscalls/wasix/sock_accept.rs b/lib/wasi/src/syscalls/wasix/sock_accept.rs index c116d0ee3..5b279a175 100644 --- a/lib/wasi/src/syscalls/wasix/sock_accept.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, @@ -20,14 +21,6 @@ pub fn sock_accept( ro_fd: WasmPtr, ro_addr: WasmPtr<__wasi_addr_port_t, M>, ) -> Result { - 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( let rights = Rights::all_socket(); let fd = wasi_try_ok!(state.fs.create_fd(rights, rights, new_flags, 0, inode)); - - debug!( - "wasi[{}:{}]::sock_accept (ret=ESUCCESS, peer={})", - ctx.data().pid(), - ctx.data().tid(), - fd - ); + Span::current().record("fd", fd); wasi_try_mem_ok!(ro_fd.write(&memory, fd)); wasi_try_ok!(crate::net::write_ip_port( diff --git a/lib/wasi/src/syscalls/wasix/sock_addr_local.rs b/lib/wasi/src/syscalls/wasix/sock_addr_local.rs index 3dcb7096f..a243b3ce5 100644 --- a/lib/wasi/src/syscalls/wasix/sock_addr_local.rs +++ b/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( 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, diff --git a/lib/wasi/src/syscalls/wasix/sock_addr_peer.rs b/lib/wasi/src/syscalls/wasix/sock_addr_peer.rs index 177db7c58..4972e64ce 100644 --- a/lib/wasi/src/syscalls/wasix/sock_addr_peer.rs +++ b/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( 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); diff --git a/lib/wasi/src/syscalls/wasix/sock_bind.rs b/lib/wasi/src/syscalls/wasix/sock_bind.rs index 9f9ab1892..b9afa6150 100644 --- a/lib/wasi/src/syscalls/wasix/sock_bind.rs +++ b/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( 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(); diff --git a/lib/wasi/src/syscalls/wasix/sock_connect.rs b/lib/wasi/src/syscalls/wasix/sock_connect.rs index 3fe85a7be..453e7cea7 100644 --- a/lib/wasi/src/syscalls/wasix/sock_connect.rs +++ b/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( 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( diff --git a/lib/wasi/src/syscalls/wasix/sock_get_opt_flag.rs b/lib/wasi/src/syscalls/wasix/sock_get_opt_flag.rs index 350f00f30..d024b2c28 100644 --- a/lib/wasi/src/syscalls/wasix/sock_get_opt_flag.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, opt: Sockoption, ret_flag: WasmPtr, ) -> 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, diff --git a/lib/wasi/src/syscalls/wasix/sock_get_opt_size.rs b/lib/wasi/src/syscalls/wasix/sock_get_opt_size.rs index f24f9b0b4..a187a00ff 100644 --- a/lib/wasi/src/syscalls/wasix/sock_get_opt_size.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, opt: Sockoption, ret_size: WasmPtr, ) -> 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, diff --git a/lib/wasi/src/syscalls/wasix/sock_get_opt_time.rs b/lib/wasi/src/syscalls/wasix/sock_get_opt_time.rs index 78bf0d784..45e5f7604 100644 --- a/lib/wasi/src/syscalls/wasix/sock_get_opt_time.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, opt: Sockoption, ret_time: WasmPtr, ) -> 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, diff --git a/lib/wasi/src/syscalls/wasix/sock_join_multicast_v4.rs b/lib/wasi/src/syscalls/wasix/sock_join_multicast_v4.rs index 758cbeb4e..a30b7d17e 100644 --- a/lib/wasi/src/syscalls/wasix/sock_join_multicast_v4.rs +++ b/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( 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)); diff --git a/lib/wasi/src/syscalls/wasix/sock_join_multicast_v6.rs b/lib/wasi/src/syscalls/wasix/sock_join_multicast_v6.rs index ddfc5fcf7..eb3964304 100644 --- a/lib/wasi/src/syscalls/wasix/sock_join_multicast_v6.rs +++ b/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( 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)); diff --git a/lib/wasi/src/syscalls/wasix/sock_leave_multicast_v4.rs b/lib/wasi/src/syscalls/wasix/sock_leave_multicast_v4.rs index 32d713405..8f0802a3a 100644 --- a/lib/wasi/src/syscalls/wasix/sock_leave_multicast_v4.rs +++ b/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( 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)); diff --git a/lib/wasi/src/syscalls/wasix/sock_leave_multicast_v6.rs b/lib/wasi/src/syscalls/wasix/sock_leave_multicast_v6.rs index 4a824fd64..76a3b719f 100644 --- a/lib/wasi/src/syscalls/wasix/sock_leave_multicast_v6.rs +++ b/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( 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)); diff --git a/lib/wasi/src/syscalls/wasix/sock_listen.rs b/lib/wasi/src/syscalls/wasix/sock_listen.rs index ea42665d1..8bb364895 100644 --- a/lib/wasi/src/syscalls/wasix/sock_listen.rs +++ b/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( 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)); diff --git a/lib/wasi/src/syscalls/wasix/sock_open.rs b/lib/wasi/src/syscalls/wasix/sock_open.rs index 704eb39e1..dd68b5c85 100644 --- a/lib/wasi/src/syscalls/wasix/sock_open.rs +++ b/lib/wasi/src/syscalls/wasix/sock_open.rs @@ -20,6 +20,7 @@ use crate::syscalls::*; /// ## Return /// /// The file descriptor of the socket that has been opened. +#[instrument(level = "debug", skip_all, fields(af, ty, pt, sock = field::Empty), ret)] pub fn sock_open( ctx: FunctionEnvMut<'_, WasiEnv>, af: Addressfamily, @@ -27,8 +28,6 @@ pub fn sock_open( pt: SockProto, ro_sock: WasmPtr, ) -> Errno { - debug!("wasi[{}:{}]::sock_open", ctx.data().pid(), ctx.data().tid()); - let env = ctx.data(); let (memory, state, inodes) = env.get_memory_and_wasi_state_and_inodes(&ctx, 0); @@ -61,6 +60,7 @@ pub fn sock_open( let fd = wasi_try!(state .fs .create_fd(rights, rights, Fdflags::empty(), 0, inode)); + Span::current().record("sock", fd); wasi_try_mem!(ro_sock.write(&memory, fd)); diff --git a/lib/wasi/src/syscalls/wasix/sock_recv.rs b/lib/wasi/src/syscalls/wasix/sock_recv.rs index 05db3734b..c921b6098 100644 --- a/lib/wasi/src/syscalls/wasix/sock_recv.rs +++ b/lib/wasi/src/syscalls/wasix/sock_recv.rs @@ -16,6 +16,7 @@ use crate::syscalls::*; /// ## Return /// /// Number of bytes stored in ri_data and message flags. +#[instrument(level = "trace", skip_all, fields(sock, nread = field::Empty), ret, err)] pub fn sock_recv( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, @@ -41,30 +42,21 @@ pub fn sock_recv( let mut ret = Errno::Success; let bytes_read = match res { Ok(bytes_read) => { - debug!( + trace!( %bytes_read, - "wasi[{}:{}]::sock_recv (fd={}, flags={:?})", - ctx.data().pid(), - ctx.data().tid(), - sock, - ri_flags ); bytes_read } Err(err) => { let socket_err = err.name(); - debug!( + trace!( %socket_err, - "wasi[{}:{}]::sock_recv (fd={}, flags={:?})", - ctx.data().pid(), - ctx.data().tid(), - sock, - ri_flags ); ret = err; 0 } }; + Span::current().record("nread", bytes_read); let env = ctx.data(); let memory = env.memory_view(&ctx); diff --git a/lib/wasi/src/syscalls/wasix/sock_recv_from.rs b/lib/wasi/src/syscalls/wasix/sock_recv_from.rs index d624dcc54..b4127856c 100644 --- a/lib/wasi/src/syscalls/wasix/sock_recv_from.rs +++ b/lib/wasi/src/syscalls/wasix/sock_recv_from.rs @@ -16,6 +16,7 @@ use crate::syscalls::*; /// ## Return /// /// Number of bytes stored in ri_data and message flags. +#[instrument(level = "trace", skip_all, fields(sock, nread = field::Empty, peer = field::Empty), ret, err)] pub fn sock_recv_from( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, @@ -26,13 +27,6 @@ pub fn sock_recv_from( ro_flags: WasmPtr, ro_addr: WasmPtr<__wasi_addr_port_t, M>, ) -> Result { - debug!( - "wasi[{}:{}]::sock_recv_from (fd={})", - ctx.data().pid(), - ctx.data().tid(), - sock - ); - wasi_try_ok!(WasiEnv::process_signals_and_exit(&mut ctx)?); let mut env = ctx.data(); @@ -103,6 +97,9 @@ pub fn sock_recv_from( } } }; + Span::current() + .record("nread", bytes_read) + .record("peer", &format!("{:?}", peer)); wasi_try_ok!(write_ip_port(&memory, ro_addr, peer.ip(), peer.port())); diff --git a/lib/wasi/src/syscalls/wasix/sock_send.rs b/lib/wasi/src/syscalls/wasix/sock_send.rs index 2df64c059..fd92f47b4 100644 --- a/lib/wasi/src/syscalls/wasix/sock_send.rs +++ b/lib/wasi/src/syscalls/wasix/sock_send.rs @@ -16,6 +16,7 @@ use crate::syscalls::*; /// ## Return /// /// Number of bytes transmitted. +#[instrument(level = "trace", skip_all, fields(sock, nsent = field::Empty), ret, err)] pub fn sock_send( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, @@ -53,30 +54,21 @@ pub fn sock_send( let mut ret = Errno::Success; let bytes_written = match res { Ok(bytes_written) => { - debug!( + trace!( %bytes_written, - "wasi[{}:{}]::sock_send (fd={}, flags={:?})", - ctx.data().pid(), - ctx.data().tid(), - sock, - si_flags ); bytes_written } Err(err) => { let socket_err = err.name(); - debug!( + trace!( %socket_err, - "wasi[{}:{}]::sock_send (fd={}, flags={:?})", - ctx.data().pid(), - ctx.data().tid(), - sock, - si_flags ); ret = err; 0 } }; + Span::current().record("nsent", bytes_written); let memory = env.memory_view(&ctx); let bytes_written: M::Offset = diff --git a/lib/wasi/src/syscalls/wasix/sock_send_file.rs b/lib/wasi/src/syscalls/wasix/sock_send_file.rs index cc0133edc..2e3be8e26 100644 --- a/lib/wasi/src/syscalls/wasix/sock_send_file.rs +++ b/lib/wasi/src/syscalls/wasix/sock_send_file.rs @@ -15,6 +15,7 @@ use crate::{syscalls::*, WasiInodes}; /// ## Return /// /// Number of bytes transmitted. +#[instrument(level = "debug", skip_all, fields(sock, in_fd, offset, count, nsent = field::Empty), ret, err)] pub fn sock_send_file( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, @@ -23,14 +24,6 @@ pub fn sock_send_file( mut count: Filesize, ret_sent: WasmPtr, ) -> Result { - debug!( - "wasi[{}:{}]::send_file (fd={}, file_fd={})", - ctx.data().pid(), - ctx.data().tid(), - sock, - in_fd - ); - wasi_try_ok!(WasiEnv::process_signals_and_exit(&mut ctx)?); let mut env = ctx.data(); @@ -193,6 +186,7 @@ pub fn sock_send_file( total_written += bytes_written as u64; } + Span::current().record("nsent", total_written); let memory = env.memory_view(&ctx); wasi_try_mem_ok!(ret_sent.write(&memory, total_written as Filesize)); diff --git a/lib/wasi/src/syscalls/wasix/sock_send_to.rs b/lib/wasi/src/syscalls/wasix/sock_send_to.rs index eb98eda42..39a501097 100644 --- a/lib/wasi/src/syscalls/wasix/sock_send_to.rs +++ b/lib/wasi/src/syscalls/wasix/sock_send_to.rs @@ -15,6 +15,7 @@ use crate::syscalls::*; /// ## Return /// /// Number of bytes transmitted. +#[instrument(level = "trace", skip_all, fields(sock, addr, nsent = field::Empty), ret, err)] pub fn sock_send_to( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, @@ -24,12 +25,6 @@ pub fn sock_send_to( addr: WasmPtr<__wasi_addr_port_t, M>, ret_data_len: WasmPtr, ) -> Result { - debug!( - "wasi[{}:{}]::sock_send_to (fd={})", - ctx.data().pid(), - ctx.data().tid(), - sock - ); let env = ctx.data(); let memory = env.memory_view(&ctx); let iovs_arr = wasi_try_mem_ok!(si_data.slice(&memory, si_data_len)); @@ -39,6 +34,7 @@ pub fn sock_send_to( wasi_try_ok!(read_ip_port(&memory, addr)) }; let addr = SocketAddr::new(addr_ip, addr_port); + Span::current().record("addr", &format!("{:?}", addr)); let bytes_written = { wasi_try_ok!(__sock_asyncify( @@ -66,6 +62,7 @@ pub fn sock_send_to( }, )) }; + Span::current().record("nsent", bytes_written); let memory = env.memory_view(&ctx); let bytes_written: M::Offset = diff --git a/lib/wasi/src/syscalls/wasix/sock_set_opt_flag.rs b/lib/wasi/src/syscalls/wasix/sock_set_opt_flag.rs index 766ee5e52..352295160 100644 --- a/lib/wasi/src/syscalls/wasix/sock_set_opt_flag.rs +++ b/lib/wasi/src/syscalls/wasix/sock_set_opt_flag.rs @@ -10,21 +10,13 @@ use crate::syscalls::*; /// * `fd` - Socket descriptor /// * `sockopt` - Socket option to be set /// * `flag` - Value to set the option to +#[instrument(level = "debug", skip_all, fields(sock, opt, flag), ret)] pub fn sock_set_opt_flag( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, opt: Sockoption, flag: Bool, ) -> Errno { - debug!( - "wasi[{}:{}]::sock_set_opt_flag(fd={}, ty={}, flag={:?})", - ctx.data().pid(), - ctx.data().tid(), - sock, - opt, - flag - ); - let flag = match flag { Bool::False => false, Bool::True => true, diff --git a/lib/wasi/src/syscalls/wasix/sock_set_opt_size.rs b/lib/wasi/src/syscalls/wasix/sock_set_opt_size.rs index 020d185a4..021508ec5 100644 --- a/lib/wasi/src/syscalls/wasix/sock_set_opt_size.rs +++ b/lib/wasi/src/syscalls/wasix/sock_set_opt_size.rs @@ -10,20 +10,13 @@ use crate::{net::socket::TimeType, syscalls::*}; /// * `fd` - Socket descriptor /// * `opt` - Socket option to be set /// * `size` - Buffer size +#[instrument(level = "debug", skip_all, fields(sock, opt, size), ret)] pub fn sock_set_opt_size( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, opt: Sockoption, size: Filesize, ) -> Errno { - debug!( - "wasi[{}:{}]::sock_set_opt_size(fd={}, ty={})", - ctx.data().pid(), - ctx.data().tid(), - sock, - opt - ); - let ty = match opt { Sockoption::RecvTimeout => TimeType::ReadTimeout, Sockoption::SendTimeout => TimeType::WriteTimeout, diff --git a/lib/wasi/src/syscalls/wasix/sock_set_opt_time.rs b/lib/wasi/src/syscalls/wasix/sock_set_opt_time.rs index 7f4f9fdb1..2f6e83c5f 100644 --- a/lib/wasi/src/syscalls/wasix/sock_set_opt_time.rs +++ b/lib/wasi/src/syscalls/wasix/sock_set_opt_time.rs @@ -9,20 +9,13 @@ use crate::{net::socket::TimeType, syscalls::*}; /// * `fd` - Socket descriptor /// * `sockopt` - Socket option to be set /// * `time` - Value to set the time to +#[instrument(level = "debug", skip_all, fields(sock, opt, time = field::Empty), ret)] pub fn sock_set_opt_time( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, opt: Sockoption, time: WasmPtr, ) -> Errno { - debug!( - "wasi[{}:{}]::sock_set_opt_time(fd={}, ty={})", - ctx.data().pid(), - ctx.data().tid(), - sock, - opt - ); - let env = ctx.data(); let memory = env.memory_view(&ctx); let time = wasi_try_mem!(time.read(&memory)); @@ -31,6 +24,7 @@ pub fn sock_set_opt_time( OptionTag::Some => Some(Duration::from_nanos(time.u)), _ => return Errno::Inval, }; + Span::current().record("time", &format!("{:?}", time)); let ty = match opt { Sockoption::RecvTimeout => TimeType::ReadTimeout, diff --git a/lib/wasi/src/syscalls/wasix/sock_shutdown.rs b/lib/wasi/src/syscalls/wasix/sock_shutdown.rs index 658a45ce3..12fdbdc6a 100644 --- a/lib/wasi/src/syscalls/wasix/sock_shutdown.rs +++ b/lib/wasi/src/syscalls/wasix/sock_shutdown.rs @@ -8,14 +8,8 @@ use crate::syscalls::*; /// ## Parameters /// /// * `how` - Which channels on the socket to shut down. +#[instrument(level = "debug", ret)] pub fn sock_shutdown(mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, how: SdFlags) -> Errno { - debug!( - "wasi[{}:{}]::sock_shutdown (fd={})", - ctx.data().pid(), - ctx.data().tid(), - sock - ); - let both = __WASI_SHUT_RD | __WASI_SHUT_WR; let how = match how { __WASI_SHUT_RD => std::net::Shutdown::Read, diff --git a/lib/wasi/src/syscalls/wasix/sock_status.rs b/lib/wasi/src/syscalls/wasix/sock_status.rs index cfdf2d49a..c1f64647b 100644 --- a/lib/wasi/src/syscalls/wasix/sock_status.rs +++ b/lib/wasi/src/syscalls/wasix/sock_status.rs @@ -3,18 +3,12 @@ use crate::syscalls::*; /// ### `sock_status()` /// Returns the current status of a socket +#[instrument(level = "debug", skip_all, fields(sock, status = field::Empty), ret)] pub fn sock_status( mut ctx: FunctionEnvMut<'_, WasiEnv>, sock: WasiFd, ret_status: WasmPtr, ) -> Errno { - debug!( - "wasi[{}:{}]::sock_status (fd={})", - ctx.data().pid(), - ctx.data().tid(), - sock - ); - let status = wasi_try!(__sock_actor( &mut ctx, sock, @@ -29,6 +23,7 @@ pub fn sock_status( WasiSocketStatus::Closed => Sockstatus::Closed, WasiSocketStatus::Failed => Sockstatus::Failed, }; + Span::current().record("status", &format!("{:?}", status)); let env = ctx.data(); let memory = env.memory_view(&ctx); diff --git a/lib/wasi/src/syscalls/wasix/stack_checkpoint.rs b/lib/wasi/src/syscalls/wasix/stack_checkpoint.rs index f514066fe..f9132222d 100644 --- a/lib/wasi/src/syscalls/wasix/stack_checkpoint.rs +++ b/lib/wasi/src/syscalls/wasix/stack_checkpoint.rs @@ -4,6 +4,7 @@ use crate::syscalls::*; /// ### `stack_checkpoint()` /// Creates a snapshot of the current stack which allows it to be restored /// later using its stack hash. +#[instrument(level = "trace", skip_all, ret, err)] pub fn stack_checkpoint( mut ctx: FunctionEnvMut<'_, WasiEnv>, snapshot_ptr: WasmPtr, @@ -15,26 +16,13 @@ pub fn stack_checkpoint( let memory = env.memory_view(&ctx); let ret_val = wasi_try_mem_ok!(ret_val.read(&memory)); if ret_val == 0 { - trace!( - "wasi[{}:{}]::stack_checkpoint - execution resumed", - ctx.data().pid(), - ctx.data().tid(), - ); + trace!("execution resumed",); } else { - trace!( - "wasi[{}:{}]::stack_checkpoint - restored - (ret={})", - ctx.data().pid(), - ctx.data().tid(), - ret_val - ); + trace!("restored - (ret={})", ret_val); } return Ok(Errno::Success); } - trace!( - "wasi[{}:{}]::stack_checkpoint - capturing", - ctx.data().pid(), - ctx.data().tid() - ); + trace!("capturing",); wasi_try_ok!(WasiEnv::process_signals_and_exit(&mut ctx)?); @@ -54,10 +42,7 @@ pub fn stack_checkpoint( // it correctly hashes if let Err(err) = snapshot_ptr.write(&memory, StackSnapshot { hash: 0, user: 0 }) { warn!( - "wasi[{}:{}]::failed to write to stack snapshot return variable - {}", - env.pid(), - env.tid(), - err + %err ); } @@ -133,25 +118,14 @@ pub fn stack_checkpoint( &rewind_stack[..], &store_data[..], ); - trace!( - "wasi[{}:{}]::stack_recorded (hash={}, user={})", - ctx.data().pid(), - ctx.data().tid(), - snapshot.hash, - snapshot.user - ); + trace!(hash = snapshot.hash, user = snapshot.user); // Save the stack snapshot let env = ctx.data(); let memory = env.memory_view(&ctx); let snapshot_ptr: WasmPtr = WasmPtr::new(snapshot_offset); if let Err(err) = snapshot_ptr.write(&memory, snapshot) { - warn!( - "wasi[{}:{}]::failed checkpoint - could not save stack snapshot - {}", - env.pid(), - env.tid(), - err - ); + warn!("could not save stack snapshot - {}", err); return OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32))); } @@ -167,8 +141,8 @@ pub fn stack_checkpoint( Errno::Success => OnCalledAction::InvokeAgain, err => { warn!( - "wasi[{}:{}]::failed checkpoint - could not rewind the stack - errno={}", - pid, tid, err + "failed checkpoint - could not rewind the stack - errno={}", + err ); OnCalledAction::Trap(Box::new(WasiError::Exit(err as u32))) } diff --git a/lib/wasi/src/syscalls/wasix/stack_restore.rs b/lib/wasi/src/syscalls/wasix/stack_restore.rs index d0bb78d6f..4c218545e 100644 --- a/lib/wasi/src/syscalls/wasix/stack_restore.rs +++ b/lib/wasi/src/syscalls/wasix/stack_restore.rs @@ -8,6 +8,7 @@ use crate::syscalls::*; /// ## Parameters /// /// * `snapshot_ptr` - Contains a previously made snapshot +#[instrument(level = "trace", skip_all, ret, err)] pub fn stack_restore( mut ctx: FunctionEnvMut<'_, WasiEnv>, snapshot_ptr: WasmPtr, @@ -18,23 +19,11 @@ pub fn stack_restore( let memory = env.memory_view(&ctx); let snapshot = match snapshot_ptr.read(&memory) { Ok(a) => { - trace!( - "wasi[{}:{}]::stack_restore (with_ret={}, hash={}, user={})", - ctx.data().pid(), - ctx.data().tid(), - val, - a.hash, - a.user - ); + trace!("with_ret={}, hash={}, user={}", val, a.hash, a.user); a } Err(err) => { - warn!( - "wasi[{}:{}]::stack_restore - failed to read stack snapshot - {}", - ctx.data().pid(), - ctx.data().tid(), - err - ); + warn!("failed to read stack snapshot - {}", err); return Err(WasiError::Exit(128)); } }; @@ -58,7 +47,13 @@ pub fn stack_restore( let offset = env.stack_base - ret_val_offset; let end = offset + (val_bytes.len() as u64); if end as usize > memory_stack.len() { - warn!("wasi[{}:{}]::snapshot stack restore failed - the return value is outside of the active part of the memory stack ({} vs {}) - {} - {}", env.pid(), env.tid(), offset, memory_stack.len(), ret_val_offset, end); + warn!( + "snapshot stack restore failed - the return value is outside of the active part of the memory stack ({} vs {}) - {} - {}", + offset, + memory_stack.len(), + ret_val_offset, + end + ); return OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32))); } else { // Update the memory stack with the new return value @@ -80,7 +75,10 @@ pub fn stack_restore( }) .unwrap_or_else(|a| a); if err != Errno::Success { - warn!("wasi[{}:{}]::snapshot stack restore failed - the return value can not be written too - {}", env.pid(), env.tid(), err); + warn!( + "snapshot stack restore failed - the return value can not be written too - {}", + err + ); return OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32))); } } @@ -92,15 +90,15 @@ pub fn stack_restore( match rewind::(ctx, memory_stack.freeze(), rewind_stack, store_data) { Errno::Success => OnCalledAction::InvokeAgain, err => { - warn!( - "wasi[{}:{}]::failed to rewind the stack - errno={}", - pid, tid, err - ); + warn!("failed to rewind the stack - errno={}", err); OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32))) } } } else { - warn!("wasi[{}:{}]::snapshot stack restore failed - the snapshot can not be found and hence restored (hash={})", env.pid(), env.tid(), snapshot.hash); + warn!( + "snapshot stack restore failed - the snapshot can not be found and hence restored (hash={})", + snapshot.hash + ); OnCalledAction::Trap(Box::new(WasiError::Exit(Errno::Fault as u32))) } }); diff --git a/lib/wasi/src/syscalls/wasix/thread_exit.rs b/lib/wasi/src/syscalls/wasix/thread_exit.rs index 533ae758f..0b5b4da36 100644 --- a/lib/wasi/src/syscalls/wasix/thread_exit.rs +++ b/lib/wasi/src/syscalls/wasix/thread_exit.rs @@ -10,14 +10,10 @@ use crate::syscalls::*; /// ## Parameters /// /// * `rval` - The exit code returned by the process. +#[instrument(level = "debug", skip_all, fields(exitcode), ret, err)] pub fn thread_exit( ctx: FunctionEnvMut<'_, WasiEnv>, exitcode: ExitCode, ) -> Result { - debug!( - "wasi[{}:{}]::thread_exit", - ctx.data().pid(), - ctx.data().tid() - ); Err(WasiError::Exit(exitcode)) } diff --git a/lib/wasi/src/syscalls/wasix/thread_id.rs b/lib/wasi/src/syscalls/wasix/thread_id.rs index 72e2303fe..85193c20e 100644 --- a/lib/wasi/src/syscalls/wasix/thread_id.rs +++ b/lib/wasi/src/syscalls/wasix/thread_id.rs @@ -4,20 +4,14 @@ use crate::syscalls::*; /// ### `thread_id()` /// Returns the index of the current thread /// (threads indices are sequencial from zero) +#[instrument(level = "trace", skip_all, fields(tid = field::Empty), ret)] pub fn thread_id( ctx: FunctionEnvMut<'_, WasiEnv>, ret_tid: WasmPtr, ) -> Errno { - /* - trace!( - "wasi[{}:{}]::thread_id", - ctx.data().pid(), - ctx.data().tid() - ); - */ - let env = ctx.data(); let tid: Tid = env.thread.tid().into(); + Span::current().record("tid", tid); let memory = env.memory_view(&ctx); wasi_try_mem!(ret_tid.write(&memory, tid)); Errno::Success diff --git a/lib/wasi/src/syscalls/wasix/thread_join.rs b/lib/wasi/src/syscalls/wasix/thread_join.rs index 066ba8dc3..db2015936 100644 --- a/lib/wasi/src/syscalls/wasix/thread_join.rs +++ b/lib/wasi/src/syscalls/wasix/thread_join.rs @@ -8,17 +8,11 @@ use crate::syscalls::*; /// ## Parameters /// /// * `tid` - Handle of the thread to wait on +#[instrument(level = "debug", skip_all, fields(join_tid), ret, err)] pub fn thread_join( mut ctx: FunctionEnvMut<'_, WasiEnv>, join_tid: Tid, ) -> Result { - debug!( - %join_tid, - "wasi[{}:{}]::thread_join", - ctx.data().pid(), - ctx.data().tid(), - ); - wasi_try_ok!(WasiEnv::process_signals_and_exit(&mut ctx)?); let env = ctx.data(); diff --git a/lib/wasi/src/syscalls/wasix/thread_local_create.rs b/lib/wasi/src/syscalls/wasix/thread_local_create.rs index df065f34b..c96ae7f60 100644 --- a/lib/wasi/src/syscalls/wasix/thread_local_create.rs +++ b/lib/wasi/src/syscalls/wasix/thread_local_create.rs @@ -10,17 +10,12 @@ use crate::syscalls::*; /// /// * `user_data` - User data that will be passed to the destructor /// when the thread variable goes out of scope +#[instrument(level = "trace", skip_all, fields(user_data), ret)] pub fn thread_local_create( ctx: FunctionEnvMut<'_, WasiEnv>, user_data: TlUser, ret_key: WasmPtr, ) -> Errno { - trace!( - "wasi[{}:{}]::thread_local_create (user_data={})", - ctx.data().pid(), - ctx.data().tid(), - user_data - ); let env = ctx.data(); let key = { diff --git a/lib/wasi/src/syscalls/wasix/thread_local_destroy.rs b/lib/wasi/src/syscalls/wasix/thread_local_destroy.rs index 4239ebd0e..f1f1281ec 100644 --- a/lib/wasi/src/syscalls/wasix/thread_local_destroy.rs +++ b/lib/wasi/src/syscalls/wasix/thread_local_destroy.rs @@ -9,13 +9,8 @@ use crate::syscalls::*; /// * `user_data` - User data that will be passed to the destructor /// when the thread variable goes out of scope /// * `key` - Thread key that was previously created +#[instrument(level = "trace", skip_all, fields(key), ret)] pub fn thread_local_destroy(mut ctx: FunctionEnvMut<'_, WasiEnv>, key: TlKey) -> Errno { - trace!( - "wasi[{}:{}]::thread_local_destroy (key={})", - ctx.data().pid(), - ctx.data().tid(), - key - ); let process = ctx.data().process.clone(); let mut inner = process.write(); diff --git a/lib/wasi/src/syscalls/wasix/thread_local_get.rs b/lib/wasi/src/syscalls/wasix/thread_local_get.rs index bcbd4ac47..cf971bf43 100644 --- a/lib/wasi/src/syscalls/wasix/thread_local_get.rs +++ b/lib/wasi/src/syscalls/wasix/thread_local_get.rs @@ -7,12 +7,12 @@ use crate::syscalls::*; /// ## Parameters /// /// * `key` - Thread key that this local variable that was previous set +#[instrument(level = "trace", skip_all, fields(key, val = field::Empty), ret)] pub fn thread_local_get( ctx: FunctionEnvMut<'_, WasiEnv>, key: TlKey, ret_val: WasmPtr, ) -> Errno { - //trace!("wasi[{}:{}]::thread_local_get (key={})", ctx.data().pid(), ctx.data().tid(), key); let env = ctx.data(); let val = { @@ -21,6 +21,8 @@ pub fn thread_local_get( guard.thread_local.get(&(current_thread, key)).copied() }; let val = val.unwrap_or_default(); + Span::current().record("val", val); + let memory = env.memory_view(&ctx); wasi_try_mem!(ret_val.write(&memory, val)); Errno::Success diff --git a/lib/wasi/src/syscalls/wasix/thread_local_set.rs b/lib/wasi/src/syscalls/wasix/thread_local_set.rs index c5ebe4d41..0de1d0285 100644 --- a/lib/wasi/src/syscalls/wasix/thread_local_set.rs +++ b/lib/wasi/src/syscalls/wasix/thread_local_set.rs @@ -8,8 +8,8 @@ use crate::syscalls::*; /// /// * `key` - Thread key that this local variable will be associated with /// * `val` - Value to be set for the thread local variable +#[instrument(level = "trace", skip_all, fields(key, val), ret)] pub fn thread_local_set(ctx: FunctionEnvMut<'_, WasiEnv>, key: TlKey, val: TlVal) -> Errno { - //trace!("wasi[{}:{}]::thread_local_set (key={}, val={})", ctx.data().pid(), ctx.data().tid(), key, val); let env = ctx.data(); let current_thread = ctx.data().thread.tid(); diff --git a/lib/wasi/src/syscalls/wasix/thread_parallelism.rs b/lib/wasi/src/syscalls/wasix/thread_parallelism.rs index daf296755..76d905072 100644 --- a/lib/wasi/src/syscalls/wasix/thread_parallelism.rs +++ b/lib/wasi/src/syscalls/wasix/thread_parallelism.rs @@ -4,21 +4,17 @@ use crate::syscalls::*; /// ### `thread_parallelism()` /// Returns the available parallelism which is normally the /// number of available cores that can run concurrently +#[instrument(level = "debug", skip_all, fields(parallelism), ret)] pub fn thread_parallelism( ctx: FunctionEnvMut<'_, WasiEnv>, ret_parallelism: WasmPtr, ) -> Errno { - debug!( - "wasi[{}:{}]::thread_parallelism", - ctx.data().pid(), - ctx.data().tid() - ); - let env = ctx.data(); let parallelism = wasi_try!(env.tasks().thread_parallelism().map_err(|err| { let err: Errno = err.into(); err })); + Span::current().record("parallelism", parallelism); let parallelism: M::Offset = wasi_try!(parallelism.try_into().map_err(|_| Errno::Overflow)); let memory = env.memory_view(&ctx); wasi_try_mem!(ret_parallelism.write(&memory, parallelism)); diff --git a/lib/wasi/src/syscalls/wasix/thread_signal.rs b/lib/wasi/src/syscalls/wasix/thread_signal.rs index a118146bf..2bb45ee33 100644 --- a/lib/wasi/src/syscalls/wasix/thread_signal.rs +++ b/lib/wasi/src/syscalls/wasix/thread_signal.rs @@ -7,18 +7,12 @@ use crate::syscalls::*; /// Inputs: /// - `Signal` /// Signal to be raised for this process +#[instrument(level = "debug", skip_all, fields(tid, sig), ret, err)] pub fn thread_signal( mut ctx: FunctionEnvMut<'_, WasiEnv>, tid: Tid, sig: Signal, ) -> Result { - debug!( - "wasi[{}:{}]::thread_signal(tid={}, sig={:?})", - ctx.data().pid(), - ctx.data().tid(), - tid, - sig - ); { let tid: WasiThreadId = tid.into(); ctx.data().process.signal_thread(&tid, sig); diff --git a/lib/wasi/src/syscalls/wasix/thread_sleep.rs b/lib/wasi/src/syscalls/wasix/thread_sleep.rs index c025edaaf..d4ae2da2d 100644 --- a/lib/wasi/src/syscalls/wasix/thread_sleep.rs +++ b/lib/wasi/src/syscalls/wasix/thread_sleep.rs @@ -7,6 +7,7 @@ use crate::syscalls::*; /// ## Parameters /// /// * `duration` - Amount of time that the thread should sleep +#[instrument(level = "debug", skip_all, fields(duration), ret, err)] pub fn thread_sleep( mut ctx: FunctionEnvMut<'_, WasiEnv>, duration: Timestamp, @@ -18,13 +19,6 @@ pub(crate) fn thread_sleep_internal( mut ctx: FunctionEnvMut<'_, WasiEnv>, duration: Timestamp, ) -> Result { - /* - trace!( - "wasi[{}:{}]::thread_sleep", - ctx.data().pid(), - ctx.data().tid() - ); - */ wasi_try_ok!(WasiEnv::process_signals_and_exit(&mut ctx)?); let env = ctx.data(); diff --git a/lib/wasi/src/syscalls/wasix/thread_spawn.rs b/lib/wasi/src/syscalls/wasix/thread_spawn.rs index abc22e541..945bcaf5d 100644 --- a/lib/wasi/src/syscalls/wasix/thread_spawn.rs +++ b/lib/wasi/src/syscalls/wasix/thread_spawn.rs @@ -21,6 +21,7 @@ use wasmer::vm::VMMemory; /// /// Returns the thread index of the newly created thread /// (indices always start from zero) +#[instrument(level = "debug", skip_all, fields(user_data, stack_base, stack_start, reactor, tid = field::Empty), ret)] pub fn thread_spawn( mut ctx: FunctionEnvMut<'_, WasiEnv>, user_data: u64, @@ -40,34 +41,22 @@ pub fn thread_spawn( Ok(h) => h, Err(err) => { error!( - "wasi[{}:{}]::thread_spawn (reactor={:?}, stack_base={}, caller_id={}) - failed to create thread handle: {}", - ctx.data().pid(), - ctx.data().tid(), - reactor, - stack_base, - current_caller_id().raw(), - err + %reactor, + %stack_base, + caller_id = current_caller_id().raw(), + "failed to create thread handle", ); // TODO: evaluate the appropriate error code, document it in the spec. return Errno::Access; } }; let thread_id: Tid = thread_handle.id().into(); - - debug!( - %thread_id, - "wasi[{}:{}]::thread_spawn (reactor={:?}, stack_base={}, caller_id={})", - ctx.data().pid(), - ctx.data().tid(), - reactor, - stack_base, - current_caller_id().raw() - ); + Span::current().record("tid", thread_id); // We need a copy of the process memory and a packaged store in order to // launch threads and reactors let thread_memory = wasi_try!(ctx.data().memory().try_clone(&ctx).ok_or_else(|| { - error!("thread failed - the memory could not be cloned"); + error!("failed - the memory could not be cloned"); Errno::Notcapable })); @@ -100,7 +89,7 @@ pub fn thread_spawn( let instance = match Instance::new(&mut store, &module, &import_object) { Ok(a) => a, Err(err) => { - error!("thread failed - create instance failed: {}", err); + error!("failed - create instance failed: {}", err); return Err(Errno::Noexec as u32); } }; @@ -110,10 +99,6 @@ pub fn thread_spawn( // Set the current thread ID ctx.data_mut(&mut store).inner = Some(WasiInstanceHandles::new(memory, &store, instance)); - trace!( - "threading: new context created for thread_id = {}", - thread.tid().raw() - ); Ok(WasiThreadContext { ctx, store: RefCell::new(store), @@ -129,11 +114,7 @@ pub fn thread_spawn( Bool::False => ctx.data(&store).inner().thread_spawn.clone().unwrap(), Bool::True => ctx.data(&store).inner().react.clone().unwrap(), _ => { - debug!( - "wasi[{}:{}]::thread_spawn - failed as the reactor type is not value", - ctx.data(&store).pid(), - ctx.data(&store).tid() - ); + debug!("failed as the reactor type is not value",); return Errno::Noexec as u32; } }; @@ -141,23 +122,10 @@ pub fn thread_spawn( let user_data_low: u32 = (user_data & 0xFFFFFFFF) as u32; let user_data_high: u32 = (user_data >> 32) as u32; - trace!( - %user_data, - "wasi[{}:{}]::thread_spawn spawn.call()", - ctx.data(&store).pid(), - ctx.data(&store).tid(), - ); - let mut ret = Errno::Success; if let Err(err) = spawn.call(store, user_data_low as i32, user_data_high as i32) { match err.downcast::() { Ok(WasiError::Exit(code)) => { - debug!( - %code, - "wasi[{}:{}]::thread_spawn - thread exited", - ctx.data(&store).pid(), - ctx.data(&store).tid(), - ); ret = if code == 0 { Errno::Success } else { @@ -165,31 +133,16 @@ pub fn thread_spawn( }; } Ok(WasiError::UnknownWasiVersion) => { - debug!( - "wasi[{}:{}]::thread_spawn - thread failed as wasi version is unknown", - ctx.data(&store).pid(), - ctx.data(&store).tid(), - ); + debug!("failed as wasi version is unknown",); ret = Errno::Noexec; } Err(err) => { - debug!( - "wasi[{}:{}]::thread_spawn - thread failed with runtime error: {}", - ctx.data(&store).pid(), - ctx.data(&store).tid(), - err - ); + debug!("failed with runtime error: {}", err); ret = Errno::Noexec; } } } - trace!( - "wasi[{}:{}]::thread_spawn - thread callback finished (reactor={:?}, ret={})", - ctx.data(&store).pid(), - ctx.data(&store).tid(), - reactor, - ret - ); + trace!("callback finished (reactor={:?}, ret={})", reactor, ret); // If we are NOT a reactor then we will only run once and need to clean up if reactor == Bool::False { @@ -244,18 +197,14 @@ pub fn thread_spawn( let memory = match memory.take() { Some(m) => m, None => { - debug!( - "thread failed - memory can only be consumed once per context creation" - ); + debug!("failed - memory can only be consumed once per context creation"); return Errno::Noexec as u32; } }; let store = match store.take() { Some(s) => s, None => { - debug!( - "thread failed - store can only be consumed once per context creation" - ); + debug!("failed - store can only be consumed once per context creation"); return Errno::Noexec as u32; } }; @@ -285,14 +234,14 @@ pub fn thread_spawn( // If the process does not export a thread spawn function then obviously // we can't spawn a background thread if env.inner().thread_spawn.is_none() { - warn!("thread failed - the program does not export a _start_thread function"); + warn!("failed - the program does not export a _start_thread function"); return Errno::Notcapable; } let spawn_type = crate::runtime::SpawnType::NewThread(thread_memory); // Now spawn a thread - trace!("threading: spawning background thread"); + trace!("spawning background thread"); let thread_module = env.inner().instance.module().clone(); let tasks2 = tasks.clone(); @@ -307,7 +256,7 @@ pub fn thread_spawn( .map_err(|err| { Into::::into(err) })); } _ => { - warn!("thread failed - invalid reactor parameter value"); + warn!("failed - invalid reactor parameter value"); return Errno::Notcapable; } } diff --git a/lib/wasi/src/syscalls/wasix/tty_get.rs b/lib/wasi/src/syscalls/wasix/tty_get.rs index e854130d5..cec02059b 100644 --- a/lib/wasi/src/syscalls/wasix/tty_get.rs +++ b/lib/wasi/src/syscalls/wasix/tty_get.rs @@ -3,11 +3,11 @@ use crate::syscalls::*; /// ### `tty_get()` /// Retrieves the current state of the TTY +#[instrument(level = "debug", skip_all, ret)] pub fn tty_get( ctx: FunctionEnvMut<'_, WasiEnv>, tty_state: WasmPtr, ) -> Errno { - debug!("wasi[{}:{}]::tty_get", ctx.data().pid(), ctx.data().tid()); let env = ctx.data(); let env = ctx.data(); diff --git a/lib/wasi/src/syscalls/wasix/tty_set.rs b/lib/wasi/src/syscalls/wasix/tty_set.rs index b6a02ec96..1a56ceecd 100644 --- a/lib/wasi/src/syscalls/wasix/tty_set.rs +++ b/lib/wasi/src/syscalls/wasix/tty_set.rs @@ -3,12 +3,11 @@ use crate::syscalls::*; /// ### `tty_set()` /// Updates the properties of the rect +#[instrument(level = "debug", skip_all, ret)] pub fn tty_set( ctx: FunctionEnvMut<'_, WasiEnv>, tty_state: WasmPtr, ) -> Errno { - debug!("wasi::tty_set"); - let env = ctx.data(); let bridge = if let Some(t) = env.runtime.tty() { t @@ -22,12 +21,9 @@ pub fn tty_set( let line_buffered = state.line_buffered; let line_feeds = true; debug!( - "wasi[{}:{}]::tty_set(echo={}, line_buffered={}, line_feeds={})", - ctx.data().pid(), - ctx.data().tid(), - echo, - line_buffered, - line_feeds + %echo, + %line_buffered, + %line_feeds ); let state = crate::os::tty::WasiTtyState {