Merge pull request #2139 from bytecodealliance/pch/wasi_common_tracing

wasi-common: switch all logs from `log` to `tracing`
This commit is contained in:
Pat Hickey
2020-08-25 15:09:53 -07:00
committed by GitHub
40 changed files with 207 additions and 184 deletions

6
Cargo.lock generated
View File

@@ -2276,8 +2276,8 @@ dependencies = [
"getrandom", "getrandom",
"lazy_static", "lazy_static",
"libc", "libc",
"log",
"thiserror", "thiserror",
"tracing",
"wig", "wig",
"wiggle", "wiggle",
"winapi", "winapi",
@@ -2613,7 +2613,7 @@ name = "wasmtime-wasi"
version = "0.19.1" version = "0.19.1"
dependencies = [ dependencies = [
"anyhow", "anyhow",
"log", "tracing",
"wasi-common", "wasi-common",
"wasmtime", "wasmtime",
"wasmtime-runtime", "wasmtime-runtime",
@@ -2788,7 +2788,7 @@ dependencies = [
"cfg-if", "cfg-if",
"filetime", "filetime",
"libc", "libc",
"log", "tracing",
] ]
[[package]] [[package]]

View File

@@ -22,11 +22,11 @@ thiserror = "1.0"
libc = "0.2" libc = "0.2"
getrandom = "0.1" getrandom = "0.1"
cfg-if = "0.1.9" cfg-if = "0.1.9"
log = "0.4"
filetime = "0.2.7" filetime = "0.2.7"
lazy_static = "1.4.0" lazy_static = "1.4.0"
wig = { path = "wig", version = "0.19.0" } wig = { path = "wig", version = "0.19.0" }
wiggle = { path = "../wiggle", default-features = false, version = "0.19.0" } wiggle = { path = "../wiggle", default-features = false, version = "0.19.0" }
tracing = "0.1.15"
[target.'cfg(unix)'.dependencies] [target.'cfg(unix)'.dependencies]
yanix = { path = "yanix", version = "0.19.0" } 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` # 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 # ecosystem of backends (e.g. `env_logger`. Disable this if you want to use
# `tracing-subscriber`. # `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 # Need to make the wiggle_metadata feature available to consumers of this
# crate if they want the snapshots to have metadata available. # crate if they want the snapshots to have metadata available.
wiggle_metadata = ["wiggle/wiggle_metadata"] wiggle_metadata = ["wiggle/wiggle_metadata"]

View File

@@ -359,7 +359,10 @@ impl WasiCtxBuilder {
self.stdout.take().unwrap(), self.stdout.take().unwrap(),
self.stderr.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 { let fd = match pending {
PendingEntry::Thunk(f) => { PendingEntry::Thunk(f) => {
let handle = EntryHandle::from(f()?); let handle = EntryHandle::from(f()?);
@@ -376,7 +379,7 @@ impl WasiCtxBuilder {
.ok_or(WasiCtxBuilderError::TooManyFilesOpen)? .ok_or(WasiCtxBuilderError::TooManyFilesOpen)?
} }
}; };
log::debug!("WasiCtx inserted at {:?}", fd); tracing::debug!(fd = tracing::field::debug(fd), "WasiCtx inserted");
} }
// Then add the preopen entries. // Then add the preopen entries.
for (guest_path, preopen) in self.preopens.take().unwrap() { for (guest_path, preopen) in self.preopens.take().unwrap() {
@@ -386,7 +389,7 @@ impl WasiCtxBuilder {
let fd = entries let fd = entries
.insert(entry) .insert(entry)
.ok_or(WasiCtxBuilderError::TooManyFilesOpen)?; .ok_or(WasiCtxBuilderError::TooManyFilesOpen)?;
log::debug!("WasiCtx inserted at {:?}", fd); tracing::debug!(fd = tracing::field::debug(fd), "WasiCtx inserted",);
} }
Ok(WasiCtx { Ok(WasiCtx {

View File

@@ -18,6 +18,12 @@ impl EntryHandle {
} }
} }
impl std::fmt::Debug for EntryHandle {
fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result {
f.debug_struct("EntryHandle").field("opaque", &()).finish()
}
}
impl From<Box<dyn Handle>> for EntryHandle { impl From<Box<dyn Handle>> for EntryHandle {
fn from(handle: Box<dyn Handle>) -> Self { fn from(handle: Box<dyn Handle>) -> Self {
Self(handle.into()) Self(handle.into())
@@ -87,10 +93,10 @@ impl Entry {
if this_rights.contains(rights) { if this_rights.contains(rights) {
Ok(()) Ok(())
} else { } else {
log::trace!( tracing::trace!(
" | validate_rights failed: required rights = {}; actual rights = {}", required = tracing::field::display(rights),
rights, actual = tracing::field::display(this_rights),
this_rights, "validate_rights failed",
); );
Err(Errno::Notcapable) Err(Errno::Notcapable)
} }

View File

@@ -287,7 +287,7 @@ impl WasiCtxBuilder {
let fd = fd_pool let fd = fd_pool
.allocate() .allocate()
.ok_or(WasiCtxBuilderError::TooManyFilesOpen)?; .ok_or(WasiCtxBuilderError::TooManyFilesOpen)?;
log::debug!("WasiCtx inserting ({:?}, {:?})", fd, pending); tracing::debug!("WasiCtx inserting ({:?}, {:?})", fd, pending);
match pending.take().unwrap() { match pending.take().unwrap() {
PendingEntry::Thunk(f) => { PendingEntry::Thunk(f) => {
entries.insert(fd, f()?); entries.insert(fd, f()?);
@@ -311,9 +311,9 @@ impl WasiCtxBuilder {
let mut fe = Entry::from(dir)?; let mut fe = Entry::from(dir)?;
fe.preopen_path = Some(guest_path); 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); entries.insert(preopen_fd, fe);
log::debug!("WasiCtx entries = {:?}", entries); tracing::debug!("WasiCtx entries = {:?}", entries);
} }
Ok(WasiCtx { Ok(WasiCtx {

View File

@@ -11,11 +11,11 @@ use crate::old::snapshot_0::wasi::{self, WasiError, WasiResult};
use crate::old::snapshot_0::{helpers, host, wasi32}; use crate::old::snapshot_0::{helpers, host, wasi32};
use crate::sandboxed_tty_writer::SandboxedTTYWriter; use crate::sandboxed_tty_writer::SandboxedTTYWriter;
use filetime::{set_file_handle_times, FileTime}; use filetime::{set_file_handle_times, FileTime};
use log::trace;
use std::fs::File; use std::fs::File;
use std::io::{self, Read, Seek, SeekFrom, Write}; use std::io::{self, Read, Seek, SeekFrom, Write};
use std::ops::DerefMut; use std::ops::DerefMut;
use std::time::{Duration, SystemTime, UNIX_EPOCH}; use std::time::{Duration, SystemTime, UNIX_EPOCH};
use tracing::trace;
pub(crate) unsafe fn fd_close( pub(crate) unsafe fn fd_close(
wasi_ctx: &mut WasiCtx, wasi_ctx: &mut WasiCtx,
@@ -686,8 +686,8 @@ pub(crate) unsafe fn path_rename(
true, true,
)?; )?;
log::debug!("path_rename resolved_old={:?}", resolved_old); tracing::debug!("path_rename resolved_old={:?}", resolved_old);
log::debug!("path_rename resolved_new={:?}", resolved_new); tracing::debug!("path_rename resolved_new={:?}", resolved_new);
hostcalls_impl::path_rename(resolved_old, resolved_new) hostcalls_impl::path_rename(resolved_old, resolved_new)
} }
@@ -950,7 +950,7 @@ pub(crate) unsafe fn path_remove_directory(
true, true,
)?; )?;
log::debug!("path_remove_directory resolved={:?}", resolved); tracing::debug!("path_remove_directory resolved={:?}", resolved);
hostcalls_impl::path_remove_directory(resolved) hostcalls_impl::path_remove_directory(resolved)
} }

View File

@@ -68,7 +68,7 @@ pub(crate) fn path_get(
loop { loop {
match path_stack.pop() { match path_stack.pop() {
Some(cur_path) => { 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 ends_with_slash = cur_path.ends_with('/');
let mut components = Path::new(&cur_path).components(); let mut components = Path::new(&cur_path).components();
@@ -86,7 +86,7 @@ pub(crate) fn path_get(
path_stack.push(tail); path_stack.push(tail);
} }
log::debug!("path_get path_stack = {:?}", path_stack); tracing::debug!("path_get path_stack = {:?}", path_stack);
match head { match head {
Component::Prefix(_) | Component::RootDir => { Component::Prefix(_) | Component::RootDir => {
@@ -140,7 +140,7 @@ pub(crate) fn path_get(
link_path.push('/'); link_path.push('/');
} }
log::debug!( tracing::debug!(
"attempted symlink expansion link_path={:?}", "attempted symlink expansion link_path={:?}",
link_path link_path
); );
@@ -172,7 +172,7 @@ pub(crate) fn path_get(
link_path.push('/'); link_path.push('/');
} }
log::debug!( tracing::debug!(
"attempted symlink expansion link_path={:?}", "attempted symlink expansion link_path={:?}",
link_path link_path
); );

View File

@@ -5,8 +5,8 @@ use crate::old::snapshot_0::memory::*;
use crate::old::snapshot_0::sys::hostcalls_impl; use crate::old::snapshot_0::sys::hostcalls_impl;
use crate::old::snapshot_0::wasi::{self, WasiError, WasiResult}; use crate::old::snapshot_0::wasi::{self, WasiError, WasiResult};
use crate::old::snapshot_0::wasi32; use crate::old::snapshot_0::wasi32;
use log::{error, trace};
use std::convert::TryFrom; use std::convert::TryFrom;
use tracing::{error, trace};
pub(crate) fn args_get( pub(crate) fn args_get(
wasi_ctx: &WasiCtx, wasi_ctx: &WasiCtx,
@@ -227,8 +227,8 @@ pub(crate) fn poll_oneoff(
let clock = unsafe { subscription.u.u.clock }; let clock = unsafe { subscription.u.u.clock };
let delay = wasi_clock_to_relative_ns_delay(clock)?; let delay = wasi_clock_to_relative_ns_delay(clock)?;
log::debug!("poll_oneoff event.u.clock = {:?}", clock); tracing::debug!("poll_oneoff event.u.clock = {:?}", clock);
log::debug!("poll_oneoff delay = {:?}ns", delay); tracing::debug!("poll_oneoff delay = {:?}ns", delay);
let current = ClockEventData { let current = ClockEventData {
delay, delay,
@@ -299,8 +299,8 @@ pub(crate) fn poll_oneoff(
} }
} }
log::debug!("poll_oneoff timeout = {:?}", timeout); tracing::debug!("poll_oneoff timeout = {:?}", timeout);
log::debug!("poll_oneoff fd_events = {:?}", fd_events); tracing::debug!("poll_oneoff fd_events = {:?}", fd_events);
hostcalls_impl::poll_oneoff(timeout, fd_events, &mut events)?; hostcalls_impl::poll_oneoff(timeout, fd_events, &mut events)?;

View File

@@ -36,7 +36,7 @@ pub(crate) fn path_unlink_file(resolved: PathGet) -> WasiResult<()> {
} }
} }
Err(err) => { Err(err) => {
log::debug!("path_unlink_file fstatat error: {:?}", err); tracing::debug!("path_unlink_file fstatat error: {:?}", err);
} }
} }
} }
@@ -50,8 +50,8 @@ pub(crate) fn path_unlink_file(resolved: PathGet) -> WasiResult<()> {
pub(crate) fn path_symlink(old_path: &str, resolved: PathGet) -> WasiResult<()> { pub(crate) fn path_symlink(old_path: &str, resolved: PathGet) -> WasiResult<()> {
use yanix::file::{fstatat, symlinkat, AtFlags}; use yanix::file::{fstatat, symlinkat, AtFlags};
log::debug!("path_symlink old_path = {:?}", old_path); tracing::debug!("path_symlink old_path = {:?}", old_path);
log::debug!("path_symlink resolved = {:?}", resolved); tracing::debug!("path_symlink resolved = {:?}", resolved);
match unsafe { symlinkat(old_path, resolved.dirfd().as_raw_fd(), resolved.path()) } { match unsafe { symlinkat(old_path, resolved.dirfd().as_raw_fd(), resolved.path()) } {
Err(err) => { Err(err) => {
@@ -71,7 +71,7 @@ pub(crate) fn path_symlink(old_path: &str, resolved: PathGet) -> WasiResult<()>
} { } {
Ok(_) => return Err(WasiError::EEXIST), Ok(_) => return Err(WasiError::EEXIST),
Err(err) => { Err(err) => {
log::debug!("path_symlink fstatat error: {:?}", err); tracing::debug!("path_symlink fstatat error: {:?}", err);
} }
} }
} }
@@ -119,7 +119,7 @@ pub(crate) fn path_rename(resolved_old: PathGet, resolved_new: PathGet) -> WasiR
} }
} }
Err(err) => { Err(err) => {
log::debug!("path_rename fstatat error: {:?}", err); tracing::debug!("path_rename fstatat error: {:?}", err);
} }
} }
} }

View File

@@ -61,14 +61,14 @@ pub(crate) unsafe fn determine_type_rights<Fd: AsRawFd>(
let file = std::mem::ManuallyDrop::new(std::fs::File::from_raw_fd(fd.as_raw_fd())); let file = std::mem::ManuallyDrop::new(std::fs::File::from_raw_fd(fd.as_raw_fd()));
let ft = file.metadata()?.file_type(); let ft = file.metadata()?.file_type();
if ft.is_block_device() { 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::__WASI_FILETYPE_BLOCK_DEVICE,
wasi::RIGHTS_BLOCK_DEVICE_BASE, wasi::RIGHTS_BLOCK_DEVICE_BASE,
wasi::RIGHTS_BLOCK_DEVICE_INHERITING, wasi::RIGHTS_BLOCK_DEVICE_INHERITING,
) )
} else if ft.is_char_device() { } 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; use yanix::file::isatty;
if isatty(fd.as_raw_fd())? { if isatty(fd.as_raw_fd())? {
( (
@@ -84,21 +84,21 @@ pub(crate) unsafe fn determine_type_rights<Fd: AsRawFd>(
) )
} }
} else if ft.is_dir() { } 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::__WASI_FILETYPE_DIRECTORY,
wasi::RIGHTS_DIRECTORY_BASE, wasi::RIGHTS_DIRECTORY_BASE,
wasi::RIGHTS_DIRECTORY_INHERITING, wasi::RIGHTS_DIRECTORY_INHERITING,
) )
} else if ft.is_file() { } 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::__WASI_FILETYPE_REGULAR_FILE,
wasi::RIGHTS_REGULAR_FILE_BASE, wasi::RIGHTS_REGULAR_FILE_BASE,
wasi::RIGHTS_REGULAR_FILE_INHERITING, wasi::RIGHTS_REGULAR_FILE_INHERITING,
) )
} else if ft.is_socket() { } 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}; use yanix::socket::{get_socket_type, SockType};
match get_socket_type(fd.as_raw_fd())? { match get_socket_type(fd.as_raw_fd())? {
SockType::Datagram => ( SockType::Datagram => (
@@ -114,14 +114,14 @@ pub(crate) unsafe fn determine_type_rights<Fd: AsRawFd>(
_ => return Err(io::Error::from_raw_os_error(libc::EINVAL)), _ => return Err(io::Error::from_raw_os_error(libc::EINVAL)),
} }
} else if ft.is_fifo() { } 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::__WASI_FILETYPE_UNKNOWN,
wasi::RIGHTS_REGULAR_FILE_BASE, wasi::RIGHTS_REGULAR_FILE_BASE,
wasi::RIGHTS_REGULAR_FILE_INHERITING, wasi::RIGHTS_REGULAR_FILE_INHERITING,
) )
} else { } 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)); return Err(io::Error::from_raw_os_error(libc::EINVAL));
} }
}; };

View File

@@ -92,12 +92,12 @@ impl From<io::Error> for WasiError {
libc::ENOTRECOVERABLE => Self::ENOTRECOVERABLE, libc::ENOTRECOVERABLE => Self::ENOTRECOVERABLE,
libc::ENOTSUP => Self::ENOTSUP, libc::ENOTSUP => Self::ENOTSUP,
x => { x => {
log::debug!("Unknown errno value: {}", x); tracing::debug!("Unknown errno value: {}", x);
Self::EIO Self::EIO
} }
}, },
None => { None => {
log::debug!("Other I/O error: {}", err); tracing::debug!("Other I/O error: {}", err);
Self::EIO Self::EIO
} }
} }

View File

@@ -115,8 +115,8 @@ pub(crate) fn path_open(
// umask is, but don't set the executable flag, because it isn't yet // umask is, but don't set the executable flag, because it isn't yet
// meaningful for WASI programs to create executable files. // meaningful for WASI programs to create executable files.
log::debug!("path_open resolved = {:?}", resolved); tracing::debug!("path_open resolved = {:?}", resolved);
log::debug!("path_open oflags = {:?}", nix_all_oflags); tracing::debug!("path_open oflags = {:?}", nix_all_oflags);
let new_fd = match unsafe { let new_fd = match unsafe {
openat( openat(
@@ -144,7 +144,7 @@ pub(crate) fn path_open(
} }
} }
Err(err) => { 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) => { 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 // Determine the type of the new file descriptor and which rights contradict with this type
Ok(unsafe { File::from_raw_fd(new_fd) }) 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, // Seek if needed. Unless cookie is wasi::__WASI_DIRCOOKIE_START,
// new items may not be returned to the caller. // new items may not be returned to the caller.
if cookie == wasi::__WASI_DIRCOOKIE_START { if cookie == wasi::__WASI_DIRCOOKIE_START {
log::trace!(" | fd_readdir: doing rewinddir"); tracing::trace!(" | fd_readdir: doing rewinddir");
dir.rewind(); dir.rewind();
} else { } 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)? }; let loc = unsafe { SeekLoc::from_raw(cookie as i64)? };
dir.seek(loc); dir.seek(loc);
} }

View File

@@ -40,7 +40,7 @@ pub(crate) fn openat(dirfd: &File, path: &str) -> WasiResult<File> {
use std::os::unix::prelude::{AsRawFd, FromRawFd}; use std::os::unix::prelude::{AsRawFd, FromRawFd};
use yanix::file::{openat, Mode}; use yanix::file::{openat, Mode};
log::debug!("path_get openat path = {:?}", path); tracing::debug!("path_get openat path = {:?}", path);
unsafe { unsafe {
openat( openat(
@@ -58,7 +58,7 @@ pub(crate) fn readlinkat(dirfd: &File, path: &str) -> WasiResult<String> {
use std::os::unix::prelude::AsRawFd; use std::os::unix::prelude::AsRawFd;
use yanix::file::readlinkat; 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) } unsafe { readlinkat(dirfd.as_raw_fd(), path) }
.map_err(Into::into) .map_err(Into::into)

View File

@@ -85,7 +85,7 @@ pub(crate) fn poll_oneoff(
let delay = timeout.delay / 1_000_000; // poll syscall requires delay to expressed in milliseconds 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()) 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 { let ready = loop {
match poll(&mut poll_fds, poll_timeout) { match poll(&mut poll_fds, poll_timeout) {
@@ -131,15 +131,15 @@ fn poll_oneoff_handle_fd_event<'a>(
use yanix::{file::fionread, poll::PollFlags}; use yanix::{file::fionread, poll::PollFlags};
for (fd_event, poll_fd) in ready_events { for (fd_event, poll_fd) in ready_events {
log::debug!("poll_oneoff_handle_fd_event fd_event = {:?}", fd_event); tracing::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() { let revents = match poll_fd.revents() {
Some(revents) => revents, Some(revents) => revents,
None => continue, 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 { let nbytes = if fd_event.r#type == wasi::__WASI_EVENTTYPE_FD_READ {
unsafe { fionread(fd_event.descriptor.as_raw_fd())? } unsafe { fionread(fd_event.descriptor.as_raw_fd())? }

View File

@@ -17,8 +17,8 @@ pub(crate) fn path_unlink_file(resolved: PathGet) -> WasiResult<()> {
pub(crate) fn path_symlink(old_path: &str, resolved: PathGet) -> WasiResult<()> { pub(crate) fn path_symlink(old_path: &str, resolved: PathGet) -> WasiResult<()> {
use yanix::file::symlinkat; use yanix::file::symlinkat;
log::debug!("path_symlink old_path = {:?}", old_path); tracing::debug!("path_symlink old_path = {:?}", old_path);
log::debug!("path_symlink resolved = {:?}", resolved); tracing::debug!("path_symlink resolved = {:?}", resolved);
unsafe { symlinkat(old_path, resolved.dirfd().as_raw_fd(), resolved.path()) } unsafe { symlinkat(old_path, resolved.dirfd().as_raw_fd(), resolved.path()) }
.map_err(Into::into) .map_err(Into::into)

View File

@@ -43,12 +43,12 @@ impl From<io::Error> for WasiError {
winerror::ERROR_DIRECTORY => Self::ENOTDIR, winerror::ERROR_DIRECTORY => Self::ENOTDIR,
winerror::ERROR_ALREADY_EXISTS => Self::EEXIST, winerror::ERROR_ALREADY_EXISTS => Self::EEXIST,
x => { x => {
log::debug!("unknown error value: {}", x); tracing::debug!("unknown error value: {}", x);
Self::EIO Self::EIO
} }
}, },
None => { None => {
log::debug!("Other I/O error: {}", err); tracing::debug!("Other I/O error: {}", err);
Self::EIO Self::EIO
} }
} }

View File

@@ -9,13 +9,13 @@ use crate::old::snapshot_0::sys::entry_impl::determine_type_rights;
use crate::old::snapshot_0::sys::host_impl::{self, path_from_host}; use crate::old::snapshot_0::sys::host_impl::{self, path_from_host};
use crate::old::snapshot_0::sys::hostcalls_impl::fs_helpers::PathGetExt; use crate::old::snapshot_0::sys::hostcalls_impl::fs_helpers::PathGetExt;
use crate::old::snapshot_0::wasi::{self, WasiError, WasiResult}; use crate::old::snapshot_0::wasi::{self, WasiError, WasiResult};
use log::{debug, trace};
use std::convert::TryInto; use std::convert::TryInto;
use std::fs::{File, Metadata, OpenOptions}; use std::fs::{File, Metadata, OpenOptions};
use std::io::{self, Seek, SeekFrom}; use std::io::{self, Seek, SeekFrom};
use std::os::windows::fs::{FileExt, OpenOptionsExt}; use std::os::windows::fs::{FileExt, OpenOptionsExt};
use std::os::windows::prelude::{AsRawHandle, FromRawHandle}; use std::os::windows::prelude::{AsRawHandle, FromRawHandle};
use std::path::{Path, PathBuf}; use std::path::{Path, PathBuf};
use tracing::{debug, trace};
use winapi::shared::winerror; use winapi::shared::winerror;
use winx::file::{AccessMode, CreationDisposition, FileModeInformation, Flags}; use winx::file::{AccessMode, CreationDisposition, FileModeInformation, Flags};
@@ -156,7 +156,7 @@ pub(crate) fn path_open(
} }
Err(err) => match err.raw_os_error() { Err(err) => match err.raw_os_error() {
Some(code) => { Some(code) => {
log::debug!("path_open at symlink_metadata error code={:?}", code); tracing::debug!("path_open at symlink_metadata error code={:?}", code);
if code as u32 != winerror::ERROR_FILE_NOT_FOUND { if code as u32 != winerror::ERROR_FILE_NOT_FOUND {
return Err(err.into()); return Err(err.into());
@@ -165,7 +165,7 @@ pub(crate) fn path_open(
// trying to open it // trying to open it
} }
None => { None => {
log::debug!("Inconvertible OS error: {}", err); tracing::debug!("Inconvertible OS error: {}", err);
return Err(WasiError::EIO); return Err(WasiError::EIO);
} }
}, },
@@ -397,7 +397,7 @@ pub(crate) fn path_rename(resolved_old: PathGet, resolved_new: PathGet) -> WasiR
}; };
match err.raw_os_error() { match err.raw_os_error() {
Some(code) => { Some(code) => {
log::debug!("path_rename at rename error code={:?}", code); tracing::debug!("path_rename at rename error code={:?}", code);
match code as u32 { match code as u32 {
winerror::ERROR_ACCESS_DENIED => { winerror::ERROR_ACCESS_DENIED => {
// So most likely dealing with new_path == dir. // So most likely dealing with new_path == dir.
@@ -427,7 +427,7 @@ pub(crate) fn path_rename(resolved_old: PathGet, resolved_new: PathGet) -> WasiR
Err(err.into()) Err(err.into())
} }
None => { None => {
log::debug!("Inconvertible OS error: {}", err); tracing::debug!("Inconvertible OS error: {}", err);
Err(WasiError::EIO) Err(WasiError::EIO)
} }
} }
@@ -474,7 +474,7 @@ pub(crate) fn path_symlink(old_path: &str, resolved: PathGet) -> WasiResult<()>
}; };
match err.raw_os_error() { match err.raw_os_error() {
Some(code) => { Some(code) => {
log::debug!("path_symlink at symlink_file error code={:?}", code); tracing::debug!("path_symlink at symlink_file error code={:?}", code);
match code as u32 { match code as u32 {
winerror::ERROR_NOT_A_REPARSE_POINT => { winerror::ERROR_NOT_A_REPARSE_POINT => {
// try creating a dir symlink instead // try creating a dir symlink instead
@@ -500,7 +500,7 @@ pub(crate) fn path_symlink(old_path: &str, resolved: PathGet) -> WasiResult<()>
Err(err.into()) Err(err.into())
} }
None => { None => {
log::debug!("Inconvertible OS error: {}", err); tracing::debug!("Inconvertible OS error: {}", err);
Err(WasiError::EIO) Err(WasiError::EIO)
} }
} }
@@ -526,7 +526,7 @@ pub(crate) fn path_unlink_file(resolved: PathGet) -> WasiResult<()> {
}; };
match err.raw_os_error() { match err.raw_os_error() {
Some(code) => { Some(code) => {
log::debug!("path_unlink_file at symlink_file error code={:?}", code); tracing::debug!("path_unlink_file at symlink_file error code={:?}", code);
if code as u32 == winerror::ERROR_ACCESS_DENIED { if code as u32 == winerror::ERROR_ACCESS_DENIED {
// try unlinking a dir symlink instead // try unlinking a dir symlink instead
return fs::remove_dir(path).map_err(Into::into); return fs::remove_dir(path).map_err(Into::into);
@@ -535,7 +535,7 @@ pub(crate) fn path_unlink_file(resolved: PathGet) -> WasiResult<()> {
Err(err.into()) Err(err.into())
} }
None => { None => {
log::debug!("Inconvertible OS error: {}", err); tracing::debug!("Inconvertible OS error: {}", err);
Err(WasiError::EIO) Err(WasiError::EIO)
} }
} }

View File

@@ -61,7 +61,7 @@ pub(crate) fn openat(dirfd: &File, path: &str) -> WasiResult<File> {
Err(e) => e, Err(e) => e,
}; };
if let Some(code) = err.raw_os_error() { if let Some(code) = err.raw_os_error() {
log::debug!("openat error={:?}", code); tracing::debug!("openat error={:?}", code);
if code as u32 == winerror::ERROR_INVALID_NAME { if code as u32 == winerror::ERROR_INVALID_NAME {
return Err(WasiError::ENOTDIR); return Err(WasiError::ENOTDIR);
} }
@@ -90,7 +90,7 @@ pub(crate) fn readlinkat(dirfd: &File, s_path: &str) -> WasiResult<String> {
Err(e) => e, Err(e) => e,
}; };
if let Some(code) = err.raw_os_error() { if let Some(code) = err.raw_os_error() {
log::debug!("readlinkat error={:?}", code); tracing::debug!("readlinkat error={:?}", code);
if code as u32 == winerror::ERROR_INVALID_NAME { if code as u32 == winerror::ERROR_INVALID_NAME {
if s_path.ends_with('/') { if s_path.ends_with('/') {
// strip "/" and check if exists // strip "/" and check if exists
@@ -130,7 +130,7 @@ pub(crate) fn concatenate<P: AsRef<Path>>(dirfd: &File, path: P) -> WasiResult<P
// components with `out_path` // components with `out_path`
let out_path = PathBuf::from(strip_extended_prefix(out_path)); let out_path = PathBuf::from(strip_extended_prefix(out_path));
log::debug!("out_path={:?}", out_path); tracing::debug!("out_path={:?}", out_path);
Ok(out_path) Ok(out_path)
} }

View File

@@ -22,7 +22,7 @@ pub(crate) fn get(
// Extract path as &str from guest's memory. // Extract path as &str from guest's memory.
let path = path_ptr.as_str()?; let path = path_ptr.as_str()?;
log::trace!(" | (path_ptr,path_len)='{}'", &*path); tracing::trace!(path = &*path);
if path.contains('\0') { if path.contains('\0') {
// if contains NUL, return Ilseq // if contains NUL, return Ilseq
@@ -55,7 +55,7 @@ pub(crate) fn get(
loop { loop {
match path_stack.pop() { match path_stack.pop() {
Some(cur_path) => { 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 ends_with_slash = cur_path.ends_with('/');
let mut components = Path::new(&cur_path).components(); let mut components = Path::new(&cur_path).components();
@@ -73,7 +73,7 @@ pub(crate) fn get(
path_stack.push(tail); 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 { match head {
Component::Prefix(_) | Component::RootDir => { Component::Prefix(_) | Component::RootDir => {
@@ -129,7 +129,7 @@ pub(crate) fn get(
link_path.push('/'); link_path.push('/');
} }
log::debug!( tracing::debug!(
"attempted symlink expansion link_path={:?}", "attempted symlink expansion link_path={:?}",
link_path link_path
); );
@@ -161,7 +161,7 @@ pub(crate) fn get(
link_path.push('/'); link_path.push('/');
} }
log::debug!( tracing::debug!(
"attempted symlink expansion link_path={:?}", "attempted symlink expansion link_path={:?}",
link_path link_path
); );

View File

@@ -9,6 +9,7 @@ pub(crate) struct ClockEventData {
pub(crate) userdata: types::Userdata, pub(crate) userdata: types::Userdata,
} }
#[derive(Debug)]
pub(crate) struct FdEventData { pub(crate) struct FdEventData {
pub(crate) handle: EntryHandle, pub(crate) handle: EntryHandle,
pub(crate) r#type: types::Eventtype, pub(crate) r#type: types::Eventtype,

View File

@@ -5,9 +5,9 @@ use crate::wasi::wasi_snapshot_preview1::WasiSnapshotPreview1;
use crate::wasi::{types, AsBytes, Errno, Result}; use crate::wasi::{types, AsBytes, Errno, Result};
use crate::WasiCtx; use crate::WasiCtx;
use crate::{path, poll}; use crate::{path, poll};
use log::{debug, error, trace};
use std::convert::TryInto; use std::convert::TryInto;
use std::io::{self, SeekFrom}; use std::io::{self, SeekFrom};
use tracing::{debug, error, trace};
use wiggle::{GuestPtr, GuestSlice}; use wiggle::{GuestPtr, GuestSlice};
impl<'a> WasiSnapshotPreview1 for WasiCtx { impl<'a> WasiSnapshotPreview1 for WasiCtx {
@@ -651,7 +651,7 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
true, true,
)?; )?;
let old_path = old_path.as_str()?; let old_path = old_path.as_str()?;
trace!(" | old_path='{}'", &*old_path); trace!(old_path = &*old_path);
new_fd.symlink(&old_path, &new_path) new_fd.symlink(&old_path, &new_path)
} }
@@ -701,8 +701,11 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
match subscription.u { match subscription.u {
types::SubscriptionU::Clock(clock) => { types::SubscriptionU::Clock(clock) => {
let delay = clock::to_relative_ns_delay(&clock)?; let delay = clock::to_relative_ns_delay(&clock)?;
debug!("poll_oneoff event.u.clock = {:?}", clock); debug!(
debug!("poll_oneoff delay = {:?}ns", delay); clock = tracing::field::debug(&clock),
delay_ns = tracing::field::debug(delay),
"poll_oneoff"
);
let current = poll::ClockEventData { let current = poll::ClockEventData {
delay, delay,
userdata: subscription.userdata, userdata: subscription.userdata,
@@ -766,8 +769,11 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
} }
} }
} }
debug!("poll_oneoff events = {:?}", events); debug!(
debug!("poll_oneoff timeout = {:?}", timeout); events = tracing::field::debug(&events),
timeout = tracing::field::debug(timeout),
"poll_oneoff"
);
// The underlying implementation should successfully and immediately return // The underlying implementation should successfully and immediately return
// if no events have been passed. Such situation may occur if all provided // if no events have been passed. Such situation may occur if all provided
// events have been filtered out as errors in the code above. // events have been filtered out as errors in the code above.
@@ -780,7 +786,7 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
event_ptr.write(event)?; event_ptr.write(event)?;
} }
trace!(" | *nevents={:?}", nevents); trace!(nevents = nevents);
Ok(nevents) Ok(nevents)
} }
@@ -803,7 +809,7 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
fn random_get(&self, buf: &GuestPtr<u8>, buf_len: types::Size) -> Result<()> { fn random_get(&self, buf: &GuestPtr<u8>, buf_len: types::Size) -> Result<()> {
let mut slice = buf.as_array(buf_len).as_slice()?; let mut slice = buf.as_array(buf_len).as_slice()?;
getrandom::getrandom(&mut *slice).map_err(|err| { getrandom::getrandom(&mut *slice).map_err(|err| {
error!("getrandom failure: {:?}", err); error!(error = tracing::field::display(err), "getrandom failure");
Errno::Io Errno::Io
}) })
} }

View File

@@ -55,7 +55,7 @@ impl AsFile for dyn Handle + 'static {
} else if let Some(other) = self.as_any().downcast_ref::<OsOther>() { } else if let Some(other) = self.as_any().downcast_ref::<OsOther>() {
other.as_file() other.as_file()
} else { } 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)) Err(io::Error::from_raw_os_error(libc::EBADF))
} }
} }
@@ -69,17 +69,26 @@ impl TryFrom<File> for Box<dyn Handle> {
match file_type { match file_type {
types::Filetype::RegularFile => { types::Filetype::RegularFile => {
let handle = OsFile::try_from(file)?; 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)) Ok(Box::new(handle))
} }
types::Filetype::Directory => { types::Filetype::Directory => {
let handle = OsDir::try_from(file)?; 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)) Ok(Box::new(handle))
} }
_ => { _ => {
let handle = OsOther::try_from(file)?; 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)) Ok(Box::new(handle))
} }
} }

View File

@@ -2,10 +2,10 @@ use super::sys_impl::oshandle::RawOsHandle;
use super::{fd, path, AsFile}; use super::{fd, path, AsFile};
use crate::handle::{Handle, HandleRights}; use crate::handle::{Handle, HandleRights};
use crate::wasi::{types, Errno, Result}; use crate::wasi::{types, Errno, Result};
use log::{debug, error};
use std::any::Any; use std::any::Any;
use std::io; use std::io;
use std::ops::Deref; use std::ops::Deref;
use tracing::{debug, error};
// TODO could this be cleaned up? // TODO could this be cleaned up?
// The actual `OsDir` struct is OS-dependent, therefore we delegate // The actual `OsDir` struct is OS-dependent, therefore we delegate

View File

@@ -24,7 +24,7 @@ pub(crate) fn unlink_file(dirfd: &OsDir, path: &str) -> Result<()> {
} }
} }
Err(err) => { Err(err) => {
log::debug!("path_unlink_file fstatat error: {:?}", err); tracing::debug!("path_unlink_file fstatat error: {:?}", err);
} }
} }
} }
@@ -38,8 +38,8 @@ pub(crate) fn unlink_file(dirfd: &OsDir, path: &str) -> Result<()> {
pub(crate) fn symlink(old_path: &str, new_dirfd: &OsDir, new_path: &str) -> Result<()> { pub(crate) fn symlink(old_path: &str, new_dirfd: &OsDir, new_path: &str) -> Result<()> {
use yanix::file::{fstatat, symlinkat, AtFlags}; use yanix::file::{fstatat, symlinkat, AtFlags};
log::debug!("path_symlink old_path = {:?}", old_path); tracing::debug!("path_symlink old_path = {:?}", old_path);
log::debug!( tracing::debug!(
"path_symlink (new_dirfd, new_path) = ({:?}, {:?})", "path_symlink (new_dirfd, new_path) = ({:?}, {:?})",
new_dirfd, new_dirfd,
new_path new_path
@@ -58,7 +58,7 @@ pub(crate) fn symlink(old_path: &str, new_dirfd: &OsDir, new_path: &str) -> Resu
{ {
Ok(_) => return Err(Errno::Exist), Ok(_) => return Err(Errno::Exist),
Err(err) => { Err(err) => {
log::debug!("path_symlink fstatat error: {:?}", err); tracing::debug!("path_symlink fstatat error: {:?}", err);
} }
} }
} }
@@ -106,7 +106,7 @@ pub(crate) fn rename(
} }
} }
Err(err) => { Err(err) => {
log::debug!("path_rename fstatat error: {:?}", err); tracing::debug!("path_rename fstatat error: {:?}", err);
} }
} }
} }

View File

@@ -59,10 +59,10 @@ pub(crate) fn readdir<'a>(
// Seek if needed. Unless cookie is wasi::__WASI_DIRCOOKIE_START, // Seek if needed. Unless cookie is wasi::__WASI_DIRCOOKIE_START,
// new items may not be returned to the caller. // new items may not be returned to the caller.
if cookie == wasi::DIRCOOKIE_START { if cookie == wasi::DIRCOOKIE_START {
log::trace!(" | fd_readdir: doing rewinddir"); tracing::trace!("fd_readdir: doing rewinddir");
dir.rewind(); dir.rewind();
} else { } 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)? }; let loc = unsafe { SeekLoc::from_raw(cookie as i64)? };
dir.seek(loc); dir.seek(loc);
} }

View File

@@ -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<()> { pub(crate) fn symlink(old_path: &str, new_dirfd: &OsDir, new_path: &str) -> Result<()> {
use yanix::file::symlinkat; use yanix::file::symlinkat;
log::debug!("path_symlink old_path = {:?}", old_path); tracing::debug!(
log::debug!( old_path = old_path,
"path_symlink (new_dirfd, new_path) = ({:?}, {:?})", new_dirfd = tracing::field::debug(new_dirfd),
new_dirfd, new_path = new_path,
new_path "path symlink"
); );
unsafe { symlinkat(old_path, new_dirfd.as_raw_fd(), new_path)? }; unsafe { symlinkat(old_path, new_dirfd.as_raw_fd(), new_path)? };

View File

@@ -50,19 +50,22 @@ impl<T: AsRawFd> AsFile for T {
pub(super) fn get_file_type(file: &File) -> io::Result<types::Filetype> { pub(super) fn get_file_type(file: &File) -> io::Result<types::Filetype> {
let ft = file.metadata()?.file_type(); let ft = file.metadata()?.file_type();
let file_type = if ft.is_block_device() { let file_type = if ft.is_block_device() {
log::debug!("Host fd {:?} is a block device", file.as_raw_fd()); tracing::debug!(
host_fd = tracing::field::display(file.as_raw_fd()),
"Host fd is a block device"
);
types::Filetype::BlockDevice types::Filetype::BlockDevice
} else if ft.is_char_device() { } 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 types::Filetype::CharacterDevice
} else if ft.is_dir() { } 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 types::Filetype::Directory
} else if ft.is_file() { } 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 types::Filetype::RegularFile
} else if ft.is_socket() { } 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}; use yanix::socket::{get_socket_type, SockType};
match unsafe { get_socket_type(file.as_raw_fd())? } { match unsafe { get_socket_type(file.as_raw_fd())? } {
SockType::Datagram => types::Filetype::SocketDgram, SockType::Datagram => types::Filetype::SocketDgram,
@@ -70,10 +73,10 @@ pub(super) fn get_file_type(file: &File) -> io::Result<types::Filetype> {
_ => return Err(io::Error::from_raw_os_error(libc::EINVAL)), _ => return Err(io::Error::from_raw_os_error(libc::EINVAL)),
} }
} else if ft.is_fifo() { } 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 types::Filetype::Unknown
} else { } 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)); return Err(io::Error::from_raw_os_error(libc::EINVAL));
}; };
Ok(file_type) Ok(file_type)
@@ -221,12 +224,12 @@ impl From<io::Error> for Errno {
libc::ENOTRECOVERABLE => Self::Notrecoverable, libc::ENOTRECOVERABLE => Self::Notrecoverable,
libc::ENOTSUP => Self::Notsup, libc::ENOTSUP => Self::Notsup,
x => { x => {
log::debug!("Unknown errno value: {}", x); tracing::debug!("Unknown errno value: {}", x);
Self::Io Self::Io
} }
}, },
None => { None => {
log::debug!("Other I/O error: {}", err); tracing::debug!("Other I/O error: {}", err);
Self::Io Self::Io
} }
} }

View File

@@ -54,7 +54,7 @@ pub(crate) fn readlinkat(dirfd: &OsDir, path: &str) -> Result<String> {
use std::os::unix::prelude::AsRawFd; use std::os::unix::prelude::AsRawFd;
use yanix::file::readlinkat; 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 = unsafe { readlinkat(dirfd.as_raw_fd(), path)? };
let path = from_host(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 // umask is, but don't set the executable flag, because it isn't yet
// meaningful for WASI programs to create executable files. // meaningful for WASI programs to create executable files.
log::debug!("path_open dirfd = {:?}", dirfd); tracing::debug!(
log::debug!("path_open path = {:?}", path); dirfd = tracing::field::debug(dirfd),
log::debug!("path_open oflags = {:?}", nix_all_oflags); path = tracing::field::debug(path),
oflags = tracing::field::debug(nix_all_oflags),
"path_open"
);
let fd_no = unsafe { let fd_no = unsafe {
openat( openat(
@@ -148,7 +151,10 @@ pub(crate) fn open(
} }
} }
Err(err) => { 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) => { 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 // Determine the type of the new file descriptor and which rights contradict with this type
let file = unsafe { File::from_raw_fd(new_fd) }; let file = unsafe { File::from_raw_fd(new_fd) };

View File

@@ -38,7 +38,10 @@ pub(crate) fn oneoff(
let delay = timeout.delay / 1_000_000; // poll syscall requires delay to expressed in milliseconds 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()) delay.try_into().unwrap_or(libc::c_int::max_value())
}); });
log::debug!("poll_oneoff poll_timeout = {:?}", poll_timeout); tracing::debug!(
poll_timeout = tracing::field::debug(poll_timeout),
"poll_oneoff"
);
let ready = loop { let ready = loop {
match poll(&mut poll_fds, poll_timeout) { match poll(&mut poll_fds, poll_timeout) {
@@ -91,16 +94,17 @@ fn handle_fd_event(
} }
for (fd_event, poll_fd) in ready_events { for (fd_event, poll_fd) in ready_events {
// log::debug!("poll_oneoff_handle_fd_event fd_event = {:?}", fd_event); tracing::debug!(
log::debug!("poll_oneoff_handle_fd_event poll_fd = {:?}", poll_fd); poll_fd = tracing::field::debug(poll_fd),
poll_event = tracing::field::debug(&fd_event),
"poll_oneoff handle_fd_event"
);
let revents = match poll_fd.revents() { let revents = match poll_fd.revents() {
Some(revents) => revents, Some(revents) => revents,
None => continue, None => continue,
}; };
log::debug!("poll_oneoff_handle_fd_event revents = {:?}", revents);
let nbytes = if fd_event.r#type == types::Eventtype::FdRead { let nbytes = if fd_event.r#type == types::Eventtype::FdRead {
query_nbytes(fd_event.handle)? query_nbytes(fd_event.handle)?
} else { } else {

View File

@@ -5,12 +5,12 @@ use crate::sys::osdir::OsDir;
use crate::sys::osfile::OsFile; use crate::sys::osfile::OsFile;
use crate::sys::AsFile; use crate::sys::AsFile;
use crate::wasi::{types, Result}; use crate::wasi::{types, Result};
use log::trace;
use std::convert::TryInto; use std::convert::TryInto;
use std::fs::{File, OpenOptions}; use std::fs::{File, OpenOptions};
use std::os::windows::fs::OpenOptionsExt; use std::os::windows::fs::OpenOptionsExt;
use std::os::windows::prelude::{AsRawHandle, FromRawHandle}; use std::os::windows::prelude::{AsRawHandle, FromRawHandle};
use std::path::Path; use std::path::Path;
use tracing::trace;
use winx::file::{AccessMode, FileModeInformation, Flags}; use winx::file::{AccessMode, FileModeInformation, Flags};
pub(crate) fn fdstat_get(file: &File) -> Result<types::Fdflags> { pub(crate) fn fdstat_get(file: &File) -> Result<types::Fdflags> {

View File

@@ -134,12 +134,12 @@ impl From<io::Error> for Errno {
winerror::ERROR_DIRECTORY => Self::Notdir, winerror::ERROR_DIRECTORY => Self::Notdir,
winerror::ERROR_ALREADY_EXISTS => Self::Exist, winerror::ERROR_ALREADY_EXISTS => Self::Exist,
x => { x => {
log::debug!("winerror: unknown error value: {}", x); tracing::debug!("winerror: unknown error value: {}", x);
Self::Io Self::Io
} }
}, },
None => { None => {
log::debug!("Other I/O error: {}", err); tracing::debug!("Other I/O error: {}", err);
Self::Io Self::Io
} }
} }

View File

@@ -46,7 +46,7 @@ fn concatenate<P: AsRef<Path>>(file: &OsDir, path: P) -> Result<PathBuf> {
// components with `out_path` // components with `out_path`
let out_path = PathBuf::from(strip_extended_prefix(out_path)); let out_path = PathBuf::from(strip_extended_prefix(out_path));
log::debug!("out_path={:?}", out_path); tracing::debug!(out_path = tracing::field::debug(&out_path));
Ok(out_path) Ok(out_path)
} }
@@ -138,7 +138,7 @@ pub(crate) fn readlinkat(dirfd: &OsDir, s_path: &str) -> Result<String> {
Err(e) => e, Err(e) => e,
}; };
if let Some(code) = err.raw_os_error() { if let Some(code) = err.raw_os_error() {
log::debug!("readlinkat error={:?}", code); tracing::debug!("readlinkat error={:?}", code);
if code as u32 == winerror::ERROR_INVALID_NAME { if code as u32 == winerror::ERROR_INVALID_NAME {
if s_path.ends_with('/') { if s_path.ends_with('/') {
// strip "/" and check if exists // strip "/" and check if exists
@@ -170,7 +170,10 @@ pub(crate) fn link(
let new_path = concatenate(new_dirfd, new_path)?; let new_path = concatenate(new_dirfd, new_path)?;
if follow_symlinks { if follow_symlinks {
// in particular, this will return an error if the target path doesn't exist // in particular, this will return an error if the target path doesn't exist
log::debug!("Following symlinks for path: {:?}", old_path); tracing::debug!(
old_path = tracing::field::display(old_path.display()),
"Following symlinks"
);
old_path = fs::canonicalize(&old_path).map_err(|e| match e.raw_os_error() { old_path = fs::canonicalize(&old_path).map_err(|e| match e.raw_os_error() {
// fs::canonicalize under Windows will return: // fs::canonicalize under Windows will return:
// * ERROR_FILE_NOT_FOUND, if it encounters a dangling symlink // * ERROR_FILE_NOT_FOUND, if it encounters a dangling symlink
@@ -184,7 +187,7 @@ pub(crate) fn link(
Err(e) => e, Err(e) => e,
}; };
if let Some(code) = err.raw_os_error() { if let Some(code) = err.raw_os_error() {
log::debug!("path_link at fs::hard_link error code={:?}", code); tracing::debug!("path_link at fs::hard_link error code={:?}", code);
if code as u32 == winerror::ERROR_ACCESS_DENIED { if code as u32 == winerror::ERROR_ACCESS_DENIED {
// If an attempt is made to create a hard link to a directory, POSIX-compliant // If an attempt is made to create a hard link to a directory, POSIX-compliant
// implementations of link return `EPERM`, but `ERROR_ACCESS_DENIED` is converted // implementations of link return `EPERM`, but `ERROR_ACCESS_DENIED` is converted
@@ -248,7 +251,7 @@ pub(crate) fn open(
} }
Err(err) => match err.raw_os_error() { Err(err) => match err.raw_os_error() {
Some(code) => { Some(code) => {
log::debug!("path_open at symlink_metadata error code={:?}", code); tracing::debug!("path_open at symlink_metadata error code={:?}", code);
match code as u32 { match code as u32 {
winerror::ERROR_FILE_NOT_FOUND => { winerror::ERROR_FILE_NOT_FOUND => {
// file not found, let it proceed to actually // file not found, let it proceed to actually
@@ -263,7 +266,7 @@ pub(crate) fn open(
}; };
} }
None => { None => {
log::debug!("Inconvertible OS error: {}", err); tracing::debug!("Inconvertible OS error: {}", err);
return Err(Errno::Io); return Err(Errno::Io);
} }
}, },
@@ -353,7 +356,7 @@ pub(crate) fn rename(
}; };
match err.raw_os_error() { match err.raw_os_error() {
Some(code) => { Some(code) => {
log::debug!("path_rename at rename error code={:?}", code); tracing::debug!("path_rename at rename error code={:?}", code);
match code as u32 { match code as u32 {
winerror::ERROR_ACCESS_DENIED => { winerror::ERROR_ACCESS_DENIED => {
// So most likely dealing with new_path == dir. // So most likely dealing with new_path == dir.
@@ -385,7 +388,7 @@ pub(crate) fn rename(
Err(err.into()) Err(err.into())
} }
None => { None => {
log::debug!("Inconvertible OS error: {}", err); tracing::debug!("Inconvertible OS error: {}", err);
Err(Errno::Io) Err(Errno::Io)
} }
} }
@@ -417,7 +420,7 @@ pub(crate) fn symlink(old_path: &str, new_dirfd: &OsDir, new_path_: &str) -> Res
}; };
match err.raw_os_error() { match err.raw_os_error() {
Some(code) => { Some(code) => {
log::debug!("path_symlink at symlink_file error code={:?}", code); tracing::debug!("path_symlink at symlink_file error code={:?}", code);
match code as u32 { match code as u32 {
// If the target contains a trailing slash, the Windows API returns // If the target contains a trailing slash, the Windows API returns
// ERROR_INVALID_NAME (which corresponds to ENOENT) instead of // ERROR_INVALID_NAME (which corresponds to ENOENT) instead of
@@ -442,7 +445,7 @@ pub(crate) fn symlink(old_path: &str, new_dirfd: &OsDir, new_path_: &str) -> Res
Err(err.into()) Err(err.into())
} }
None => { None => {
log::debug!("Inconvertible OS error: {}", err); tracing::debug!("Inconvertible OS error: {}", err);
Err(Errno::Io) Err(Errno::Io)
} }
} }
@@ -468,7 +471,7 @@ pub(crate) fn unlink_file(dirfd: &OsDir, path: &str) -> Result<()> {
}; };
match err.raw_os_error() { match err.raw_os_error() {
Some(code) => { Some(code) => {
log::debug!("path_unlink_file at symlink_file error code={:?}", code); tracing::debug!("path_unlink_file at symlink_file error code={:?}", code);
if code as u32 == winerror::ERROR_ACCESS_DENIED { if code as u32 == winerror::ERROR_ACCESS_DENIED {
// try unlinking a dir symlink instead // try unlinking a dir symlink instead
return fs::remove_dir(path).map_err(Into::into); return fs::remove_dir(path).map_err(Into::into);
@@ -477,7 +480,7 @@ pub(crate) fn unlink_file(dirfd: &OsDir, path: &str) -> Result<()> {
Err(err.into()) Err(err.into())
} }
None => { None => {
log::debug!("Inconvertible OS error: {}", err); tracing::debug!("Inconvertible OS error: {}", err);
Err(Errno::Io) Err(Errno::Io)
} }
} }

View File

@@ -7,12 +7,12 @@ use crate::sys::stdio::{Stderr, Stdin, Stdout};
use crate::sys::AsFile; use crate::sys::AsFile;
use crate::wasi::{types, Errno, Result}; use crate::wasi::{types, Errno, Result};
use lazy_static::lazy_static; use lazy_static::lazy_static;
use log::{debug, error, trace, warn};
use std::convert::TryInto; use std::convert::TryInto;
use std::sync::mpsc::{self, Receiver, RecvTimeoutError, Sender, TryRecvError}; use std::sync::mpsc::{self, Receiver, RecvTimeoutError, Sender, TryRecvError};
use std::sync::Mutex; use std::sync::Mutex;
use std::thread; use std::thread;
use std::time::Duration; use std::time::Duration;
use tracing::{debug, error, trace, warn};
struct StdinPoll { struct StdinPoll {
request_tx: Sender<()>, request_tx: Sender<()>,
@@ -241,7 +241,7 @@ pub(crate) fn oneoff(
handle_error_event(event, Errno::Notsup, events); handle_error_event(event, Errno::Notsup, events);
} }
} else { } else {
log::error!("can poll FdEvent for OS resources only"); tracing::error!("can poll FdEvent for OS resources only");
return Err(Errno::Badf); return Err(Errno::Badf);
} }
} }

View File

@@ -1,6 +1,5 @@
use crate::handle::{Handle, HandleRights}; use crate::handle::{Handle, HandleRights};
use crate::wasi::{self, types, Errno, Result, RightsExt}; use crate::wasi::{self, types, Errno, Result, RightsExt};
use log::trace;
use std::any::Any; use std::any::Any;
use std::cell::{Cell, RefCell}; use std::cell::{Cell, RefCell};
use std::collections::hash_map::Entry; use std::collections::hash_map::Entry;
@@ -10,6 +9,7 @@ use std::io;
use std::io::SeekFrom; use std::io::SeekFrom;
use std::path::{Path, PathBuf}; use std::path::{Path, PathBuf};
use std::rc::Rc; use std::rc::Rc;
use tracing::trace;
pub mod pipe; pub mod pipe;
@@ -96,7 +96,7 @@ impl FileContents for VecFileContents {
} }
fn pread(&self, buf: &mut [u8], offset: types::Filesize) -> Result<usize> { fn pread(&self, buf: &mut [u8], offset: types::Filesize) -> Result<usize> {
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 offset: usize = offset.try_into().map_err(|_| Errno::Inval)?;
let data_remaining = self.content.len().saturating_sub(offset); 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]); (&mut buf[..read_count]).copy_from_slice(&self.content[offset..][..read_count]);
let res = Ok(read_count); Ok(read_count)
trace!(" | pread={:?}", res);
res
} }
fn pwrite(&mut self, buf: &[u8], offset: types::Filesize) -> Result<usize> { fn pwrite(&mut self, buf: &[u8], offset: types::Filesize) -> Result<usize> {
@@ -347,26 +345,16 @@ impl Handle for InMemoryFile {
fn openat( fn openat(
&self, &self,
path: &str, path: &str,
read: bool, _read: bool,
write: bool, _write: bool,
oflags: types::Oflags, oflags: types::Oflags,
fd_flags: types::Fdflags, _fd_flags: types::Fdflags,
) -> Result<Box<dyn Handle>> { ) -> Result<Box<dyn Handle>> {
log::trace!(
"InMemoryFile::openat(path={:?}, read={:?}, write={:?}, oflags={:?}, fd_flags={:?}",
path,
read,
write,
oflags,
fd_flags
);
if oflags.contains(&types::Oflags::DIRECTORY) { if oflags.contains(&types::Oflags::DIRECTORY) {
log::trace!( tracing::trace!(
"InMemoryFile::openat was passed oflags DIRECTORY, but {:?} is a file.", "InMemoryFile::openat was passed oflags DIRECTORY, but {:?} is a file.",
path path
); );
log::trace!(" return Notdir");
return Err(Errno::Notdir); return Err(Errno::Notdir);
} }
@@ -526,7 +514,7 @@ impl Handle for VirtualDir {
type Item = Result<(types::Dirent, String)>; type Item = Result<(types::Dirent, String)>;
fn next(&mut self) -> Option<Self::Item> { fn next(&mut self) -> Option<Self::Item> {
log::trace!("VirtualDirIter::next continuing from {}", self.start); tracing::trace!("VirtualDirIter::next continuing from {}", self.start);
if self.start == SELF_DIR_COOKIE { if self.start == SELF_DIR_COOKIE {
self.start += 1; self.start += 1;
let name = ".".to_owned(); let name = ".".to_owned();
@@ -645,20 +633,11 @@ impl Handle for VirtualDir {
fn openat( fn openat(
&self, &self,
path: &str, path: &str,
read: bool, _read: bool,
write: bool, _write: bool,
oflags: types::Oflags, oflags: types::Oflags,
fd_flags: types::Fdflags, fd_flags: types::Fdflags,
) -> Result<Box<dyn Handle>> { ) -> Result<Box<dyn Handle>> {
log::trace!(
"VirtualDir::openat(path={:?}, read={:?}, write={:?}, oflags={:?}, fd_flags={:?}",
path,
read,
write,
oflags,
fd_flags
);
if path == "." { if path == "." {
return self.try_clone().map_err(Into::into); return self.try_clone().map_err(Into::into);
} else if path == ".." { } else if path == ".." {
@@ -681,19 +660,17 @@ impl Handle for VirtualDir {
Entry::Occupied(e) => { Entry::Occupied(e) => {
let creat_excl_mask = types::Oflags::CREAT | types::Oflags::EXCL; let creat_excl_mask = types::Oflags::CREAT | types::Oflags::EXCL;
if (oflags & creat_excl_mask) == creat_excl_mask { if (oflags & creat_excl_mask) == creat_excl_mask {
log::trace!("VirtualDir::openat was passed oflags CREAT|EXCL, but the file {:?} exists.", file_name); tracing::trace!("VirtualDir::openat was passed oflags CREAT|EXCL, but the file {:?} exists.", file_name);
log::trace!(" return Exist");
return Err(Errno::Exist); return Err(Errno::Exist);
} }
if oflags.contains(&types::Oflags::DIRECTORY) if oflags.contains(&types::Oflags::DIRECTORY)
&& e.get().get_file_type() != types::Filetype::Directory && e.get().get_file_type() != types::Filetype::Directory
{ {
log::trace!( tracing::trace!(
"VirtualDir::openat was passed oflags DIRECTORY, but {:?} is a file.", "VirtualDir::openat was passed oflags DIRECTORY, but {:?} is a file.",
file_name file_name
); );
log::trace!(" return Notdir");
return Err(Errno::Notdir); return Err(Errno::Notdir);
} }
@@ -709,7 +686,7 @@ impl Handle for VirtualDir {
return Err(Errno::Nospc); 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()); let file = Box::new(InMemoryFile::memory_backed());
file.fd_flags.set(fd_flags); file.fd_flags.set(fd_flags);
@@ -757,7 +734,7 @@ impl Handle for VirtualDir {
Ok(()) Ok(())
} }
Entry::Vacant(_) => { Entry::Vacant(_) => {
log::trace!( tracing::trace!(
"VirtualDir::remove_directory failed to remove {}, no such entry", "VirtualDir::remove_directory failed to remove {}, no such entry",
trimmed_path trimmed_path
); );
@@ -798,7 +775,7 @@ impl Handle for VirtualDir {
Ok(()) Ok(())
} }
Entry::Vacant(_) => { Entry::Vacant(_) => {
log::trace!( tracing::trace!(
"VirtualDir::unlink_file failed to remove {}, no such entry", "VirtualDir::unlink_file failed to remove {}, no such entry",
trimmed_path trimmed_path
); );

View File

@@ -96,7 +96,7 @@ fn generate_wrappers(func: &witx::InterfaceFunc, old: bool) -> TokenStream {
let ret = #call let ret = #call
.err() .err()
.unwrap_or(super::wasi::WasiError::ESUCCESS); .unwrap_or(super::wasi::WasiError::ESUCCESS);
log::trace!(" | errno={}", ret); tracing::trace!(" | errno={}", ret);
ret.as_raw_errno() ret.as_raw_errno()
} }
}; };

View File

@@ -201,7 +201,7 @@ pub fn define_struct(args: TokenStream) -> TokenStream {
let #name_ident = wasmtime::Func::wrap( let #name_ident = wasmtime::Func::wrap(
store, store,
move |caller: wasmtime::Caller<'_> #(,#shim_arg_decls)*| -> #ret_ty { move |caller: wasmtime::Caller<'_> #(,#shim_arg_decls)*| -> #ret_ty {
log::trace!( tracing::trace!(
#format_str, #format_str,
#(#format_args),* #(#format_args),*
); );
@@ -209,7 +209,7 @@ pub fn define_struct(args: TokenStream) -> TokenStream {
let memory = match caller.get_export("memory") { let memory = match caller.get_export("memory") {
Some(wasmtime::Extern::Memory(m)) => m, 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; let e = wasi_common::old::snapshot_0::wasi::__WASI_ERRNO_INVAL;
#handle_early_error #handle_early_error
} }

View File

@@ -9,7 +9,7 @@ repository = "https://github.com/bytecodealliance/wasmtime"
edition = "2018" edition = "2018"
[dependencies] [dependencies]
log = "0.4" tracing = "0.1.15"
libc = { version = "0.2", features = ["extra_traits"] } libc = { version = "0.2", features = ["extra_traits"] }
bitflags = "1.2" bitflags = "1.2"
cfg-if = "0.1.9" cfg-if = "0.1.9"

View File

@@ -25,7 +25,7 @@ impl FileTimeExt for filetime::FileTime {
let sec = match self.seconds().try_into() { let sec = match self.seconds().try_into() {
Ok(sec) => sec, Ok(sec) => sec,
Err(_) => { Err(_) => {
log::debug!("filetime_to_timespec failed converting seconds to required width"); tracing::debug!("filetime_to_timespec failed converting seconds to required width");
return Err(Error::from_raw_os_error(libc::EOVERFLOW)); return Err(Error::from_raw_os_error(libc::EOVERFLOW));
} }
}; };

View File

@@ -51,7 +51,9 @@ pub unsafe fn posix_fadvise(
// is providing a dubiously large hint. This is not confirmed (no helpful info in the man // is providing a dubiously large hint. This is not confirmed (no helpful info in the man
// pages), but offhand, a 2+ GiB advisory read async seems unlikely to help with any kind // pages), but offhand, a 2+ GiB advisory read async seems unlikely to help with any kind
// of performance, so we log and exit early with a no-op. // of performance, so we log and exit early with a no-op.
log::warn!("`len` too big to fit in the host's command. Returning early with no-op!"); tracing::warn!(
"`len` too big to fit in the host's command. Returning early with no-op!"
);
return Ok(()); return Ok(());
} }
}; };

View File

@@ -13,7 +13,7 @@ edition = "2018"
[dependencies] [dependencies]
anyhow = "1.0" anyhow = "1.0"
log = { version = "0.4.8", default-features = false } tracing = "0.1.15"
wasi-common = { path = "../wasi-common", version = "0.19.0" } wasi-common = { path = "../wasi-common", version = "0.19.0" }
wasmtime = { path = "../wasmtime", version = "0.19.0", default-features = false } wasmtime = { path = "../wasmtime", version = "0.19.0", default-features = false }
wasmtime-runtime = { path = "../runtime", version = "0.19.0" } wasmtime-runtime = { path = "../runtime", version = "0.19.0" }