diff --git a/Cargo.lock b/Cargo.lock index 9e19c67c2e..bd3f302bf5 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2324,8 +2324,8 @@ dependencies = [ "getrandom", "lazy_static", "libc", - "log", "thiserror", + "tracing", "wig", "wiggle", "winapi", @@ -2629,7 +2629,7 @@ name = "wasmtime-wasi" version = "0.19.1" dependencies = [ "anyhow", - "log", + "tracing", "wasi-common", "wasmtime", "wasmtime-runtime", diff --git a/crates/wasi-common/Cargo.toml b/crates/wasi-common/Cargo.toml index c92e98a5e8..6a26b7129c 100644 --- a/crates/wasi-common/Cargo.toml +++ b/crates/wasi-common/Cargo.toml @@ -22,11 +22,11 @@ thiserror = "1.0" libc = "0.2" getrandom = "0.1" cfg-if = "0.1.9" -log = "0.4" filetime = "0.2.7" lazy_static = "1.4.0" wig = { path = "wig", version = "0.19.0" } wiggle = { path = "../wiggle", default-features = false, version = "0.19.0" } +tracing = "0.1.15" [target.'cfg(unix)'.dependencies] yanix = { path = "yanix", version = "0.19.0" } @@ -44,7 +44,7 @@ default = ["trace_log"] # This feature enables the `tracing` logs in the calls to target the `log` # ecosystem of backends (e.g. `env_logger`. Disable this if you want to use # `tracing-subscriber`. -trace_log = [ "wiggle/tracing_log" ] +trace_log = [ "wiggle/tracing_log", "tracing/log" ] # Need to make the wiggle_metadata feature available to consumers of this # crate if they want the snapshots to have metadata available. wiggle_metadata = ["wiggle/wiggle_metadata"] diff --git a/crates/wasi-common/src/ctx.rs b/crates/wasi-common/src/ctx.rs index 05bb0fce94..9d2ffd54f1 100644 --- a/crates/wasi-common/src/ctx.rs +++ b/crates/wasi-common/src/ctx.rs @@ -359,7 +359,10 @@ impl WasiCtxBuilder { self.stdout.take().unwrap(), self.stderr.take().unwrap(), ] { - log::debug!("WasiCtx inserting entry {:?}", pending); + tracing::debug!( + pending = tracing::field::debug(&pending), + "WasiCtx inserting entry" + ); let fd = match pending { PendingEntry::Thunk(f) => { let handle = EntryHandle::from(f()?); @@ -376,7 +379,7 @@ impl WasiCtxBuilder { .ok_or(WasiCtxBuilderError::TooManyFilesOpen)? } }; - log::debug!("WasiCtx inserted at {:?}", fd); + tracing::debug!(fd = tracing::field::debug(fd), "WasiCtx inserted"); } // Then add the preopen entries. for (guest_path, preopen) in self.preopens.take().unwrap() { @@ -386,7 +389,7 @@ impl WasiCtxBuilder { let fd = entries .insert(entry) .ok_or(WasiCtxBuilderError::TooManyFilesOpen)?; - log::debug!("WasiCtx inserted at {:?}", fd); + tracing::debug!(fd = tracing::field::debug(fd), "WasiCtx inserted",); } Ok(WasiCtx { diff --git a/crates/wasi-common/src/entry.rs b/crates/wasi-common/src/entry.rs index ba9e90c160..8734c63d3f 100644 --- a/crates/wasi-common/src/entry.rs +++ b/crates/wasi-common/src/entry.rs @@ -87,10 +87,10 @@ impl Entry { if this_rights.contains(rights) { Ok(()) } else { - log::trace!( - " | validate_rights failed: required rights = {}; actual rights = {}", - rights, - this_rights, + tracing::trace!( + required = tracing::field::display(rights), + actual = tracing::field::display(this_rights), + "validate_rights failed", ); Err(Errno::Notcapable) } diff --git a/crates/wasi-common/src/old/snapshot_0/ctx.rs b/crates/wasi-common/src/old/snapshot_0/ctx.rs index 28c1cac673..7ffa536bf3 100644 --- a/crates/wasi-common/src/old/snapshot_0/ctx.rs +++ b/crates/wasi-common/src/old/snapshot_0/ctx.rs @@ -287,7 +287,7 @@ impl WasiCtxBuilder { let fd = fd_pool .allocate() .ok_or(WasiCtxBuilderError::TooManyFilesOpen)?; - log::debug!("WasiCtx inserting ({:?}, {:?})", fd, pending); + tracing::debug!("WasiCtx inserting ({:?}, {:?})", fd, pending); match pending.take().unwrap() { PendingEntry::Thunk(f) => { entries.insert(fd, f()?); @@ -311,9 +311,9 @@ impl WasiCtxBuilder { let mut fe = Entry::from(dir)?; fe.preopen_path = Some(guest_path); - log::debug!("WasiCtx inserting ({:?}, {:?})", preopen_fd, fe); + tracing::debug!("WasiCtx inserting ({:?}, {:?})", preopen_fd, fe); entries.insert(preopen_fd, fe); - log::debug!("WasiCtx entries = {:?}", entries); + tracing::debug!("WasiCtx entries = {:?}", entries); } Ok(WasiCtx { diff --git a/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/fs.rs b/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/fs.rs index 8d71856682..6ba1c4d99b 100644 --- a/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/fs.rs +++ b/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/fs.rs @@ -11,11 +11,11 @@ use crate::old::snapshot_0::wasi::{self, WasiError, WasiResult}; use crate::old::snapshot_0::{helpers, host, wasi32}; use crate::sandboxed_tty_writer::SandboxedTTYWriter; use filetime::{set_file_handle_times, FileTime}; -use log::trace; use std::fs::File; use std::io::{self, Read, Seek, SeekFrom, Write}; use std::ops::DerefMut; use std::time::{Duration, SystemTime, UNIX_EPOCH}; +use tracing::trace; pub(crate) unsafe fn fd_close( wasi_ctx: &mut WasiCtx, @@ -686,8 +686,8 @@ pub(crate) unsafe fn path_rename( true, )?; - log::debug!("path_rename resolved_old={:?}", resolved_old); - log::debug!("path_rename resolved_new={:?}", resolved_new); + tracing::debug!("path_rename resolved_old={:?}", resolved_old); + tracing::debug!("path_rename resolved_new={:?}", resolved_new); hostcalls_impl::path_rename(resolved_old, resolved_new) } @@ -950,7 +950,7 @@ pub(crate) unsafe fn path_remove_directory( true, )?; - log::debug!("path_remove_directory resolved={:?}", resolved); + tracing::debug!("path_remove_directory resolved={:?}", resolved); hostcalls_impl::path_remove_directory(resolved) } diff --git a/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/fs_helpers.rs b/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/fs_helpers.rs index aabdb29da2..59a94d1bec 100644 --- a/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/fs_helpers.rs +++ b/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/fs_helpers.rs @@ -68,7 +68,7 @@ pub(crate) fn path_get( loop { match path_stack.pop() { Some(cur_path) => { - log::debug!("path_get cur_path = {:?}", cur_path); + tracing::debug!("path_get cur_path = {:?}", cur_path); let ends_with_slash = cur_path.ends_with('/'); let mut components = Path::new(&cur_path).components(); @@ -86,7 +86,7 @@ pub(crate) fn path_get( path_stack.push(tail); } - log::debug!("path_get path_stack = {:?}", path_stack); + tracing::debug!("path_get path_stack = {:?}", path_stack); match head { Component::Prefix(_) | Component::RootDir => { @@ -140,7 +140,7 @@ pub(crate) fn path_get( link_path.push('/'); } - log::debug!( + tracing::debug!( "attempted symlink expansion link_path={:?}", link_path ); @@ -172,7 +172,7 @@ pub(crate) fn path_get( link_path.push('/'); } - log::debug!( + tracing::debug!( "attempted symlink expansion link_path={:?}", link_path ); diff --git a/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/misc.rs b/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/misc.rs index d6f4d24684..7016fb2162 100644 --- a/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/misc.rs +++ b/crates/wasi-common/src/old/snapshot_0/hostcalls_impl/misc.rs @@ -5,8 +5,8 @@ use crate::old::snapshot_0::memory::*; use crate::old::snapshot_0::sys::hostcalls_impl; use crate::old::snapshot_0::wasi::{self, WasiError, WasiResult}; use crate::old::snapshot_0::wasi32; -use log::{error, trace}; use std::convert::TryFrom; +use tracing::{error, trace}; pub(crate) fn args_get( wasi_ctx: &WasiCtx, @@ -227,8 +227,8 @@ pub(crate) fn poll_oneoff( let clock = unsafe { subscription.u.u.clock }; let delay = wasi_clock_to_relative_ns_delay(clock)?; - log::debug!("poll_oneoff event.u.clock = {:?}", clock); - log::debug!("poll_oneoff delay = {:?}ns", delay); + tracing::debug!("poll_oneoff event.u.clock = {:?}", clock); + tracing::debug!("poll_oneoff delay = {:?}ns", delay); let current = ClockEventData { delay, @@ -299,8 +299,8 @@ pub(crate) fn poll_oneoff( } } - log::debug!("poll_oneoff timeout = {:?}", timeout); - log::debug!("poll_oneoff fd_events = {:?}", fd_events); + tracing::debug!("poll_oneoff timeout = {:?}", timeout); + tracing::debug!("poll_oneoff fd_events = {:?}", fd_events); hostcalls_impl::poll_oneoff(timeout, fd_events, &mut events)?; diff --git a/crates/wasi-common/src/old/snapshot_0/sys/unix/entry_impl.rs b/crates/wasi-common/src/old/snapshot_0/sys/unix/entry_impl.rs index 8f9debabf9..325c627f60 100644 --- a/crates/wasi-common/src/old/snapshot_0/sys/unix/entry_impl.rs +++ b/crates/wasi-common/src/old/snapshot_0/sys/unix/entry_impl.rs @@ -61,14 +61,14 @@ pub(crate) unsafe fn determine_type_rights( let file = std::mem::ManuallyDrop::new(std::fs::File::from_raw_fd(fd.as_raw_fd())); let ft = file.metadata()?.file_type(); if ft.is_block_device() { - log::debug!("Host fd {:?} is a block device", fd.as_raw_fd()); + tracing::debug!("Host fd {:?} is a block device", fd.as_raw_fd()); ( wasi::__WASI_FILETYPE_BLOCK_DEVICE, wasi::RIGHTS_BLOCK_DEVICE_BASE, wasi::RIGHTS_BLOCK_DEVICE_INHERITING, ) } else if ft.is_char_device() { - log::debug!("Host fd {:?} is a char device", fd.as_raw_fd()); + tracing::debug!("Host fd {:?} is a char device", fd.as_raw_fd()); use yanix::file::isatty; if isatty(fd.as_raw_fd())? { ( @@ -84,21 +84,21 @@ pub(crate) unsafe fn determine_type_rights( ) } } else if ft.is_dir() { - log::debug!("Host fd {:?} is a directory", fd.as_raw_fd()); + tracing::debug!("Host fd {:?} is a directory", fd.as_raw_fd()); ( wasi::__WASI_FILETYPE_DIRECTORY, wasi::RIGHTS_DIRECTORY_BASE, wasi::RIGHTS_DIRECTORY_INHERITING, ) } else if ft.is_file() { - log::debug!("Host fd {:?} is a file", fd.as_raw_fd()); + tracing::debug!("Host fd {:?} is a file", fd.as_raw_fd()); ( wasi::__WASI_FILETYPE_REGULAR_FILE, wasi::RIGHTS_REGULAR_FILE_BASE, wasi::RIGHTS_REGULAR_FILE_INHERITING, ) } else if ft.is_socket() { - log::debug!("Host fd {:?} is a socket", fd.as_raw_fd()); + tracing::debug!("Host fd {:?} is a socket", fd.as_raw_fd()); use yanix::socket::{get_socket_type, SockType}; match get_socket_type(fd.as_raw_fd())? { SockType::Datagram => ( @@ -114,14 +114,14 @@ pub(crate) unsafe fn determine_type_rights( _ => return Err(io::Error::from_raw_os_error(libc::EINVAL)), } } else if ft.is_fifo() { - log::debug!("Host fd {:?} is a fifo", fd.as_raw_fd()); + tracing::debug!("Host fd {:?} is a fifo", fd.as_raw_fd()); ( wasi::__WASI_FILETYPE_UNKNOWN, wasi::RIGHTS_REGULAR_FILE_BASE, wasi::RIGHTS_REGULAR_FILE_INHERITING, ) } else { - log::debug!("Host fd {:?} is unknown", fd.as_raw_fd()); + tracing::debug!("Host fd {:?} is unknown", fd.as_raw_fd()); return Err(io::Error::from_raw_os_error(libc::EINVAL)); } }; diff --git a/crates/wasi-common/src/old/snapshot_0/sys/unix/host_impl.rs b/crates/wasi-common/src/old/snapshot_0/sys/unix/host_impl.rs index 50e294dd2a..c6ff0fac3e 100644 --- a/crates/wasi-common/src/old/snapshot_0/sys/unix/host_impl.rs +++ b/crates/wasi-common/src/old/snapshot_0/sys/unix/host_impl.rs @@ -92,12 +92,12 @@ impl From for WasiError { libc::ENOTRECOVERABLE => Self::ENOTRECOVERABLE, libc::ENOTSUP => Self::ENOTSUP, x => { - log::debug!("Unknown errno value: {}", x); + tracing::debug!("Unknown errno value: {}", x); Self::EIO } }, None => { - log::debug!("Other I/O error: {}", err); + tracing::debug!("Other I/O error: {}", err); Self::EIO } } diff --git a/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/fs.rs b/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/fs.rs index cfbbb1ead5..f618dfca8c 100644 --- a/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/fs.rs +++ b/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/fs.rs @@ -115,8 +115,8 @@ pub(crate) fn path_open( // umask is, but don't set the executable flag, because it isn't yet // meaningful for WASI programs to create executable files. - log::debug!("path_open resolved = {:?}", resolved); - log::debug!("path_open oflags = {:?}", nix_all_oflags); + tracing::debug!("path_open resolved = {:?}", resolved); + tracing::debug!("path_open oflags = {:?}", nix_all_oflags); let new_fd = match unsafe { openat( @@ -144,7 +144,7 @@ pub(crate) fn path_open( } } Err(err) => { - log::debug!("path_open fstatat error: {:?}", err); + tracing::debug!("path_open fstatat error: {:?}", err); } } } @@ -166,7 +166,7 @@ pub(crate) fn path_open( } } Err(err) => { - log::debug!("path_open fstatat error: {:?}", err); + tracing::debug!("path_open fstatat error: {:?}", err); } } } @@ -182,7 +182,7 @@ pub(crate) fn path_open( } }; - log::debug!("path_open (host) new_fd = {:?}", new_fd); + tracing::debug!("path_open (host) new_fd = {:?}", new_fd); // Determine the type of the new file descriptor and which rights contradict with this type Ok(unsafe { File::from_raw_fd(new_fd) }) @@ -294,10 +294,10 @@ pub(crate) fn fd_readdir<'a>( // Seek if needed. Unless cookie is wasi::__WASI_DIRCOOKIE_START, // new items may not be returned to the caller. if cookie == wasi::__WASI_DIRCOOKIE_START { - log::trace!(" | fd_readdir: doing rewinddir"); + tracing::trace!(" | fd_readdir: doing rewinddir"); dir.rewind(); } else { - log::trace!(" | fd_readdir: doing seekdir to {}", cookie); + tracing::trace!(" | fd_readdir: doing seekdir to {}", cookie); let loc = unsafe { SeekLoc::from_raw(cookie as i64)? }; dir.seek(loc); } diff --git a/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/fs_helpers.rs b/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/fs_helpers.rs index 23ad31a578..4d812ebe02 100644 --- a/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/fs_helpers.rs +++ b/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/fs_helpers.rs @@ -40,7 +40,7 @@ pub(crate) fn openat(dirfd: &File, path: &str) -> WasiResult { use std::os::unix::prelude::{AsRawFd, FromRawFd}; use yanix::file::{openat, Mode}; - log::debug!("path_get openat path = {:?}", path); + tracing::debug!("path_get openat path = {:?}", path); unsafe { openat( @@ -58,7 +58,7 @@ pub(crate) fn readlinkat(dirfd: &File, path: &str) -> WasiResult { use std::os::unix::prelude::AsRawFd; use yanix::file::readlinkat; - log::debug!("path_get readlinkat path = {:?}", path); + tracing::debug!("path_get readlinkat path = {:?}", path); unsafe { readlinkat(dirfd.as_raw_fd(), path) } .map_err(Into::into) diff --git a/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/misc.rs b/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/misc.rs index 914a25d94a..015f942efe 100644 --- a/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/misc.rs +++ b/crates/wasi-common/src/old/snapshot_0/sys/unix/hostcalls_impl/misc.rs @@ -85,7 +85,7 @@ pub(crate) fn poll_oneoff( let delay = timeout.delay / 1_000_000; // poll syscall requires delay to expressed in milliseconds delay.try_into().unwrap_or(libc::c_int::max_value()) }); - log::debug!("poll_oneoff poll_timeout = {:?}", poll_timeout); + tracing::debug!("poll_oneoff poll_timeout = {:?}", poll_timeout); let ready = loop { match poll(&mut poll_fds, poll_timeout) { @@ -131,15 +131,15 @@ fn poll_oneoff_handle_fd_event<'a>( use yanix::{file::fionread, poll::PollFlags}; for (fd_event, poll_fd) in ready_events { - log::debug!("poll_oneoff_handle_fd_event fd_event = {:?}", fd_event); - log::debug!("poll_oneoff_handle_fd_event poll_fd = {:?}", poll_fd); + tracing::debug!("poll_oneoff_handle_fd_event fd_event = {:?}", fd_event); + tracing::debug!("poll_oneoff_handle_fd_event poll_fd = {:?}", poll_fd); let revents = match poll_fd.revents() { Some(revents) => revents, None => continue, }; - log::debug!("poll_oneoff_handle_fd_event revents = {:?}", revents); + tracing::debug!("poll_oneoff_handle_fd_event revents = {:?}", revents); let nbytes = if fd_event.r#type == wasi::__WASI_EVENTTYPE_FD_READ { unsafe { fionread(fd_event.descriptor.as_raw_fd())? } diff --git a/crates/wasi-common/src/old/snapshot_0/sys/unix/linux/hostcalls_impl.rs b/crates/wasi-common/src/old/snapshot_0/sys/unix/linux/hostcalls_impl.rs index 8380f1742e..6489b5bf30 100644 --- a/crates/wasi-common/src/old/snapshot_0/sys/unix/linux/hostcalls_impl.rs +++ b/crates/wasi-common/src/old/snapshot_0/sys/unix/linux/hostcalls_impl.rs @@ -17,8 +17,8 @@ pub(crate) fn path_unlink_file(resolved: PathGet) -> WasiResult<()> { pub(crate) fn path_symlink(old_path: &str, resolved: PathGet) -> WasiResult<()> { use yanix::file::symlinkat; - log::debug!("path_symlink old_path = {:?}", old_path); - log::debug!("path_symlink resolved = {:?}", resolved); + tracing::debug!("path_symlink old_path = {:?}", old_path); + tracing::debug!("path_symlink resolved = {:?}", resolved); unsafe { symlinkat(old_path, resolved.dirfd().as_raw_fd(), resolved.path()) } .map_err(Into::into) diff --git a/crates/wasi-common/src/path.rs b/crates/wasi-common/src/path.rs index fdce7b481a..99452a7b17 100644 --- a/crates/wasi-common/src/path.rs +++ b/crates/wasi-common/src/path.rs @@ -22,7 +22,7 @@ pub(crate) fn get( // Extract path as &str from guest's memory. let path = path_ptr.as_str()?; - log::trace!(" | (path_ptr,path_len)='{}'", &*path); + tracing::trace!(path = &*path); if path.contains('\0') { // if contains NUL, return Ilseq @@ -55,7 +55,7 @@ pub(crate) fn get( loop { match path_stack.pop() { Some(cur_path) => { - log::debug!("path_get cur_path = {:?}", cur_path); + tracing::debug!(cur_path = tracing::field::display(&cur_path), "path get"); let ends_with_slash = cur_path.ends_with('/'); let mut components = Path::new(&cur_path).components(); @@ -73,7 +73,7 @@ pub(crate) fn get( path_stack.push(tail); } - log::debug!("path_get path_stack = {:?}", path_stack); + tracing::debug!(path_stack = tracing::field::debug(&path_stack), "path_get"); match head { Component::Prefix(_) | Component::RootDir => { @@ -129,7 +129,7 @@ pub(crate) fn get( link_path.push('/'); } - log::debug!( + tracing::debug!( "attempted symlink expansion link_path={:?}", link_path ); @@ -161,7 +161,7 @@ pub(crate) fn get( link_path.push('/'); } - log::debug!( + tracing::debug!( "attempted symlink expansion link_path={:?}", link_path ); diff --git a/crates/wasi-common/src/snapshots/wasi_snapshot_preview1.rs b/crates/wasi-common/src/snapshots/wasi_snapshot_preview1.rs index a6d3d97d44..342fbad1d4 100644 --- a/crates/wasi-common/src/snapshots/wasi_snapshot_preview1.rs +++ b/crates/wasi-common/src/snapshots/wasi_snapshot_preview1.rs @@ -5,9 +5,9 @@ use crate::wasi::wasi_snapshot_preview1::WasiSnapshotPreview1; use crate::wasi::{types, AsBytes, Errno, Result}; use crate::WasiCtx; use crate::{path, poll}; -use log::{debug, error, trace}; use std::convert::TryInto; use std::io::{self, SeekFrom}; +use tracing::{debug, error, trace}; use wiggle::{GuestPtr, GuestSlice}; impl<'a> WasiSnapshotPreview1 for WasiCtx { @@ -651,7 +651,7 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx { true, )?; let old_path = old_path.as_str()?; - trace!(" | old_path='{}'", &*old_path); + trace!(old_path = &*old_path); new_fd.symlink(&old_path, &new_path) } @@ -701,8 +701,11 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx { match subscription.u { types::SubscriptionU::Clock(clock) => { let delay = clock::to_relative_ns_delay(&clock)?; - debug!("poll_oneoff event.u.clock = {:?}", clock); - debug!("poll_oneoff delay = {:?}ns", delay); + debug!( + clock = tracing::field::debug(&clock), + delay_ns = tracing::field::debug(delay), + "poll_oneoff" + ); let current = poll::ClockEventData { delay, userdata: subscription.userdata, @@ -766,8 +769,11 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx { } } } - debug!("poll_oneoff events = {:?}", events); - debug!("poll_oneoff timeout = {:?}", timeout); + debug!( + events = tracing::field::debug(&events), + timeout = tracing::field::debug(timeout), + "poll_oneoff" + ); // The underlying implementation should successfully and immediately return // if no events have been passed. Such situation may occur if all provided // events have been filtered out as errors in the code above. @@ -780,7 +786,7 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx { event_ptr.write(event)?; } - trace!(" | *nevents={:?}", nevents); + trace!(nevents = nevents); Ok(nevents) } @@ -803,7 +809,7 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx { fn random_get(&self, buf: &GuestPtr, buf_len: types::Size) -> Result<()> { let mut slice = buf.as_array(buf_len).as_slice()?; getrandom::getrandom(&mut *slice).map_err(|err| { - error!("getrandom failure: {:?}", err); + error!(error = tracing::field::display(err), "getrandom failure"); Errno::Io }) } diff --git a/crates/wasi-common/src/sys/mod.rs b/crates/wasi-common/src/sys/mod.rs index bca99f146d..a07603034f 100644 --- a/crates/wasi-common/src/sys/mod.rs +++ b/crates/wasi-common/src/sys/mod.rs @@ -55,7 +55,7 @@ impl AsFile for dyn Handle + 'static { } else if let Some(other) = self.as_any().downcast_ref::() { other.as_file() } else { - log::error!("tried to make std::fs::File from non-OS handle"); + tracing::error!("tried to make std::fs::File from non-OS handle"); Err(io::Error::from_raw_os_error(libc::EBADF)) } } @@ -69,17 +69,26 @@ impl TryFrom for Box { match file_type { types::Filetype::RegularFile => { let handle = OsFile::try_from(file)?; - log::debug!("Created new instance of OsFile: {:?}", handle); + tracing::debug!( + handle = tracing::field::debug(&handle), + "Created new instance of OsFile" + ); Ok(Box::new(handle)) } types::Filetype::Directory => { let handle = OsDir::try_from(file)?; - log::debug!("Created new instance of OsDir: {:?}", handle); + tracing::debug!( + handle = tracing::field::debug(&handle), + "Created new instance of OsDir" + ); Ok(Box::new(handle)) } _ => { let handle = OsOther::try_from(file)?; - log::debug!("Created new instance of OsOther: {:?}", handle); + tracing::debug!( + handle = tracing::field::debug(&handle), + "Created new instance of OsOther" + ); Ok(Box::new(handle)) } } diff --git a/crates/wasi-common/src/sys/osdir.rs b/crates/wasi-common/src/sys/osdir.rs index 6ba3cc63a9..bf8bb0c280 100644 --- a/crates/wasi-common/src/sys/osdir.rs +++ b/crates/wasi-common/src/sys/osdir.rs @@ -2,10 +2,10 @@ use super::sys_impl::oshandle::RawOsHandle; use super::{fd, path, AsFile}; use crate::handle::{Handle, HandleRights}; use crate::wasi::{types, Errno, Result}; -use log::{debug, error}; use std::any::Any; use std::io; use std::ops::Deref; +use tracing::{debug, error}; // TODO could this be cleaned up? // The actual `OsDir` struct is OS-dependent, therefore we delegate diff --git a/crates/wasi-common/src/sys/unix/fd.rs b/crates/wasi-common/src/sys/unix/fd.rs index 83d717711c..5a84e51d5e 100644 --- a/crates/wasi-common/src/sys/unix/fd.rs +++ b/crates/wasi-common/src/sys/unix/fd.rs @@ -59,10 +59,10 @@ pub(crate) fn readdir<'a>( // Seek if needed. Unless cookie is wasi::__WASI_DIRCOOKIE_START, // new items may not be returned to the caller. if cookie == wasi::DIRCOOKIE_START { - log::trace!(" | fd_readdir: doing rewinddir"); + tracing::trace!("fd_readdir: doing rewinddir"); dir.rewind(); } else { - log::trace!(" | fd_readdir: doing seekdir to {}", cookie); + tracing::trace!("fd_readdir: doing seekdir to {}", cookie); let loc = unsafe { SeekLoc::from_raw(cookie as i64)? }; dir.seek(loc); } diff --git a/crates/wasi-common/src/sys/unix/linux/path.rs b/crates/wasi-common/src/sys/unix/linux/path.rs index 9bbcb34514..1d441a3fa9 100644 --- a/crates/wasi-common/src/sys/unix/linux/path.rs +++ b/crates/wasi-common/src/sys/unix/linux/path.rs @@ -11,11 +11,11 @@ pub(crate) fn unlink_file(dirfd: &OsDir, path: &str) -> Result<()> { pub(crate) fn symlink(old_path: &str, new_dirfd: &OsDir, new_path: &str) -> Result<()> { use yanix::file::symlinkat; - log::debug!("path_symlink old_path = {:?}", old_path); - log::debug!( - "path_symlink (new_dirfd, new_path) = ({:?}, {:?})", - new_dirfd, - new_path + tracing::debug!( + old_path = old_path, + new_dirfd = tracing::field::debug(new_dirfd), + new_path = new_path, + "path symlink" ); unsafe { symlinkat(old_path, new_dirfd.as_raw_fd(), new_path)? }; diff --git a/crates/wasi-common/src/sys/unix/mod.rs b/crates/wasi-common/src/sys/unix/mod.rs index 7a28810509..79ab5c9010 100644 --- a/crates/wasi-common/src/sys/unix/mod.rs +++ b/crates/wasi-common/src/sys/unix/mod.rs @@ -50,19 +50,19 @@ impl AsFile for T { pub(super) fn get_file_type(file: &File) -> io::Result { let ft = file.metadata()?.file_type(); let file_type = if ft.is_block_device() { - log::debug!("Host fd {:?} is a block device", file.as_raw_fd()); + tracing::debug!("Host fd {:?} is a block device", file.as_raw_fd()); types::Filetype::BlockDevice } else if ft.is_char_device() { - log::debug!("Host fd {:?} is a char device", file.as_raw_fd()); + tracing::debug!("Host fd {:?} is a char device", file.as_raw_fd()); types::Filetype::CharacterDevice } else if ft.is_dir() { - log::debug!("Host fd {:?} is a directory", file.as_raw_fd()); + tracing::debug!("Host fd {:?} is a directory", file.as_raw_fd()); types::Filetype::Directory } else if ft.is_file() { - log::debug!("Host fd {:?} is a file", file.as_raw_fd()); + tracing::debug!("Host fd {:?} is a file", file.as_raw_fd()); types::Filetype::RegularFile } else if ft.is_socket() { - log::debug!("Host fd {:?} is a socket", file.as_raw_fd()); + tracing::debug!("Host fd {:?} is a socket", file.as_raw_fd()); use yanix::socket::{get_socket_type, SockType}; match unsafe { get_socket_type(file.as_raw_fd())? } { SockType::Datagram => types::Filetype::SocketDgram, @@ -70,10 +70,10 @@ pub(super) fn get_file_type(file: &File) -> io::Result { _ => return Err(io::Error::from_raw_os_error(libc::EINVAL)), } } else if ft.is_fifo() { - log::debug!("Host fd {:?} is a fifo", file.as_raw_fd()); + tracing::debug!("Host fd {:?} is a fifo", file.as_raw_fd()); types::Filetype::Unknown } else { - log::debug!("Host fd {:?} is unknown", file.as_raw_fd()); + tracing::debug!("Host fd {:?} is unknown", file.as_raw_fd()); return Err(io::Error::from_raw_os_error(libc::EINVAL)); }; Ok(file_type) @@ -221,12 +221,12 @@ impl From for Errno { libc::ENOTRECOVERABLE => Self::Notrecoverable, libc::ENOTSUP => Self::Notsup, x => { - log::debug!("Unknown errno value: {}", x); + tracing::debug!("Unknown errno value: {}", x); Self::Io } }, None => { - log::debug!("Other I/O error: {}", err); + tracing::debug!("Other I/O error: {}", err); Self::Io } } diff --git a/crates/wasi-common/src/sys/unix/path.rs b/crates/wasi-common/src/sys/unix/path.rs index fcaf98a96b..d109fe96f5 100644 --- a/crates/wasi-common/src/sys/unix/path.rs +++ b/crates/wasi-common/src/sys/unix/path.rs @@ -54,7 +54,7 @@ pub(crate) fn readlinkat(dirfd: &OsDir, path: &str) -> Result { use std::os::unix::prelude::AsRawFd; use yanix::file::readlinkat; - log::debug!("path_get readlinkat path = {:?}", path); + tracing::debug!(path = path, "path_get readlinkat"); let path = unsafe { readlinkat(dirfd.as_raw_fd(), path)? }; let path = from_host(path)?; @@ -123,9 +123,12 @@ pub(crate) fn open( // umask is, but don't set the executable flag, because it isn't yet // meaningful for WASI programs to create executable files. - log::debug!("path_open dirfd = {:?}", dirfd); - log::debug!("path_open path = {:?}", path); - log::debug!("path_open oflags = {:?}", nix_all_oflags); + tracing::debug!( + dirfd = tracing::field::debug(dirfd), + path = tracing::field::debug(path), + oflags = tracing::field::debug(nix_all_oflags), + "path_open" + ); let fd_no = unsafe { openat( @@ -148,7 +151,10 @@ pub(crate) fn open( } } Err(err) => { - log::debug!("path_open fstatat error: {:?}", err); + tracing::debug!( + error = tracing::field::debug(&err), + "path_open fstatat error", + ); } } } @@ -164,7 +170,10 @@ pub(crate) fn open( } } Err(err) => { - log::debug!("path_open fstatat error: {:?}", err); + tracing::debug!( + error = tracing::field::debug(&err), + "path_open fstatat error", + ); } } } @@ -180,7 +189,7 @@ pub(crate) fn open( } }; - log::debug!("path_open (host) new_fd = {:?}", new_fd); + tracing::debug!(new_fd = tracing::field::debug(new_fd)); // Determine the type of the new file descriptor and which rights contradict with this type let file = unsafe { File::from_raw_fd(new_fd) }; diff --git a/crates/wasi-common/src/sys/unix/poll.rs b/crates/wasi-common/src/sys/unix/poll.rs index b185bdb93c..8b30861b8d 100644 --- a/crates/wasi-common/src/sys/unix/poll.rs +++ b/crates/wasi-common/src/sys/unix/poll.rs @@ -38,7 +38,7 @@ pub(crate) fn oneoff( let delay = timeout.delay / 1_000_000; // poll syscall requires delay to expressed in milliseconds delay.try_into().unwrap_or(libc::c_int::max_value()) }); - log::debug!("poll_oneoff poll_timeout = {:?}", poll_timeout); + tracing::debug!("poll_oneoff poll_timeout = {:?}", poll_timeout); let ready = loop { match poll(&mut poll_fds, poll_timeout) { @@ -91,15 +91,14 @@ fn handle_fd_event( } for (fd_event, poll_fd) in ready_events { - // log::debug!("poll_oneoff_handle_fd_event fd_event = {:?}", fd_event); - log::debug!("poll_oneoff_handle_fd_event poll_fd = {:?}", poll_fd); + tracing::debug!("poll_oneoff_handle_fd_event poll_fd = {:?}", poll_fd); let revents = match poll_fd.revents() { Some(revents) => revents, None => continue, }; - log::debug!("poll_oneoff_handle_fd_event revents = {:?}", revents); + tracing::debug!("poll_oneoff_handle_fd_event revents = {:?}", revents); let nbytes = if fd_event.r#type == types::Eventtype::FdRead { query_nbytes(fd_event.handle)? diff --git a/crates/wasi-common/src/virtfs.rs b/crates/wasi-common/src/virtfs.rs index 0f20ddb509..2b4cd6649f 100644 --- a/crates/wasi-common/src/virtfs.rs +++ b/crates/wasi-common/src/virtfs.rs @@ -1,6 +1,5 @@ use crate::handle::{Handle, HandleRights}; use crate::wasi::{self, types, Errno, Result, RightsExt}; -use log::trace; use std::any::Any; use std::cell::{Cell, RefCell}; use std::collections::hash_map::Entry; @@ -10,6 +9,7 @@ use std::io; use std::io::SeekFrom; use std::path::{Path, PathBuf}; use std::rc::Rc; +use tracing::trace; pub mod pipe; @@ -96,7 +96,7 @@ impl FileContents for VecFileContents { } fn pread(&self, buf: &mut [u8], offset: types::Filesize) -> Result { - trace!(" | pread(buf.len={}, offset={})", buf.len(), offset); + trace!(buffer_length = buf.len(), offset = offset, "pread"); let offset: usize = offset.try_into().map_err(|_| Errno::Inval)?; let data_remaining = self.content.len().saturating_sub(offset); @@ -105,9 +105,7 @@ impl FileContents for VecFileContents { (&mut buf[..read_count]).copy_from_slice(&self.content[offset..][..read_count]); - let res = Ok(read_count); - trace!(" | pread={:?}", res); - res + Ok(read_count) } fn pwrite(&mut self, buf: &[u8], offset: types::Filesize) -> Result { @@ -352,21 +350,11 @@ impl Handle for InMemoryFile { oflags: types::Oflags, fd_flags: types::Fdflags, ) -> Result> { - log::trace!( - "InMemoryFile::openat(path={:?}, read={:?}, write={:?}, oflags={:?}, fd_flags={:?}", - path, - read, - write, - oflags, - fd_flags - ); - if oflags.contains(&types::Oflags::DIRECTORY) { - log::trace!( + tracing::trace!( "InMemoryFile::openat was passed oflags DIRECTORY, but {:?} is a file.", path ); - log::trace!(" return Notdir"); return Err(Errno::Notdir); } @@ -526,7 +514,7 @@ impl Handle for VirtualDir { type Item = Result<(types::Dirent, String)>; fn next(&mut self) -> Option { - log::trace!("VirtualDirIter::next continuing from {}", self.start); + tracing::trace!("VirtualDirIter::next continuing from {}", self.start); if self.start == SELF_DIR_COOKIE { self.start += 1; let name = ".".to_owned(); @@ -650,15 +638,6 @@ impl Handle for VirtualDir { oflags: types::Oflags, fd_flags: types::Fdflags, ) -> Result> { - log::trace!( - "VirtualDir::openat(path={:?}, read={:?}, write={:?}, oflags={:?}, fd_flags={:?}", - path, - read, - write, - oflags, - fd_flags - ); - if path == "." { return self.try_clone().map_err(Into::into); } else if path == ".." { @@ -681,19 +660,17 @@ impl Handle for VirtualDir { Entry::Occupied(e) => { let creat_excl_mask = types::Oflags::CREAT | types::Oflags::EXCL; if (oflags & creat_excl_mask) == creat_excl_mask { - log::trace!("VirtualDir::openat was passed oflags CREAT|EXCL, but the file {:?} exists.", file_name); - log::trace!(" return Exist"); + tracing::trace!("VirtualDir::openat was passed oflags CREAT|EXCL, but the file {:?} exists.", file_name); return Err(Errno::Exist); } if oflags.contains(&types::Oflags::DIRECTORY) && e.get().get_file_type() != types::Filetype::Directory { - log::trace!( + tracing::trace!( "VirtualDir::openat was passed oflags DIRECTORY, but {:?} is a file.", file_name ); - log::trace!(" return Notdir"); return Err(Errno::Notdir); } @@ -709,7 +686,7 @@ impl Handle for VirtualDir { return Err(Errno::Nospc); } - log::trace!("VirtualDir::openat creating an InMemoryFile named {}", path); + tracing::trace!("VirtualDir::openat creating an InMemoryFile named {}", path); let file = Box::new(InMemoryFile::memory_backed()); file.fd_flags.set(fd_flags); @@ -757,7 +734,7 @@ impl Handle for VirtualDir { Ok(()) } Entry::Vacant(_) => { - log::trace!( + tracing::trace!( "VirtualDir::remove_directory failed to remove {}, no such entry", trimmed_path ); @@ -798,7 +775,7 @@ impl Handle for VirtualDir { Ok(()) } Entry::Vacant(_) => { - log::trace!( + tracing::trace!( "VirtualDir::unlink_file failed to remove {}, no such entry", trimmed_path ); diff --git a/crates/wasi-common/wig/src/hostcalls.rs b/crates/wasi-common/wig/src/hostcalls.rs index 2ea4e6e5eb..a01926743b 100644 --- a/crates/wasi-common/wig/src/hostcalls.rs +++ b/crates/wasi-common/wig/src/hostcalls.rs @@ -96,7 +96,7 @@ fn generate_wrappers(func: &witx::InterfaceFunc, old: bool) -> TokenStream { let ret = #call .err() .unwrap_or(super::wasi::WasiError::ESUCCESS); - log::trace!(" | errno={}", ret); + tracing::trace!(" | errno={}", ret); ret.as_raw_errno() } }; diff --git a/crates/wasi-common/wig/src/wasi.rs b/crates/wasi-common/wig/src/wasi.rs index 9e31879659..60269d28f7 100644 --- a/crates/wasi-common/wig/src/wasi.rs +++ b/crates/wasi-common/wig/src/wasi.rs @@ -201,7 +201,7 @@ pub fn define_struct(args: TokenStream) -> TokenStream { let #name_ident = wasmtime::Func::wrap( store, move |caller: wasmtime::Caller<'_> #(,#shim_arg_decls)*| -> #ret_ty { - log::trace!( + tracing::trace!( #format_str, #(#format_args),* ); @@ -209,7 +209,7 @@ pub fn define_struct(args: TokenStream) -> TokenStream { let memory = match caller.get_export("memory") { Some(wasmtime::Extern::Memory(m)) => m, _ => { - log::warn!("callee does not export a memory as \"memory\""); + tracing::warn!("callee does not export a memory as \"memory\""); let e = wasi_common::old::snapshot_0::wasi::__WASI_ERRNO_INVAL; #handle_early_error }