Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improvements to the tracing and logging in wasmer #3644

Merged
merged 7 commits into from
Mar 7, 2023
Merged
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 2 additions & 1 deletion Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

2 changes: 2 additions & 0 deletions flake.nix
Original file line number Diff line number Diff line change
@@ -38,6 +38,8 @@
src = self;
buildInputs = with pkgs; [
pkgconfig
libffi
libxml2
openssl
llvmPackages_14.llvm
# Snapshot testing
8 changes: 7 additions & 1 deletion lib/api/src/function_env.rs
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
use std::{any::Any, marker::PhantomData};
use std::{any::Any, fmt::Debug, marker::PhantomData};

use crate::vm::VMFunctionEnvironment;

@@ -102,6 +102,12 @@ pub struct FunctionEnvMut<'a, T: 'a> {
pub(crate) func_env: FunctionEnv<T>,
}

impl<'a, T> Debug for FunctionEnvMut<'a, T> {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
write!(f, "env_mut")
}
}

impl<T: Send + 'static> FunctionEnvMut<'_, T> {
/// Returns a reference to the host state in this function environement.
pub fn data(&self) -> &T {
7 changes: 1 addition & 6 deletions lib/api/src/ptr.rs
Original file line number Diff line number Diff line change
@@ -278,11 +278,6 @@ impl<T: ValueType, M: MemorySize> Eq for WasmPtr<T, M> {}

impl<T: ValueType, M: MemorySize> fmt::Debug for WasmPtr<T, M> {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
write!(
f,
"WasmPtr(offset: {}, pointer: {:#x})",
self.offset.into(),
self.offset.into()
)
write!(f, "{}(@{})", std::any::type_name::<T>(), self.offset.into())
}
}
8 changes: 5 additions & 3 deletions lib/cli/Cargo.toml
Original file line number Diff line number Diff line change
@@ -54,8 +54,6 @@ distance = "0.4"
# For the inspect subcommand
bytesize = "1.0"
cfg-if = "1.0"
# For debug feature
fern = { version = "0.6", features = ["colored"], optional = true }
tempfile = "3.4.0"
http_req = { version="^0.8", default-features = false, features = ["rust-tls"] }
reqwest = { version = "^0.11", default-features = false, features = ["rustls-tls", "json", "multipart"] }
@@ -91,6 +89,8 @@ pathdiff = "0.2.1"
sha2 = "0.10.6"
object = "0.30.0"
wasm-coredump-builder = { version = "0.1.11" }
tracing = { version = "0.1", optional = true }
tracing-subscriber = { version = "0.3", features = [ "env-filter", "fmt" ], optional = true }

[build-dependencies]
chrono = { version = "^0.4", default-features = false, features = [ "std", "clock" ] }
@@ -111,6 +111,7 @@ default = [
"wasmer-artifact-create",
"static-artifact-create",
"webc_runner",
"tracing"
]
cache = ["wasmer-cache"]
cache-blake3-pure = ["wasmer-cache/blake3-pure"]
@@ -163,10 +164,11 @@ llvm = [
"wasmer-compiler-llvm",
"compiler",
]
debug = ["fern", "wasmer-wasi/logging"]
debug = ["tracing", "wasmer-wasi/logging"]
disable-all-logging = ["wasmer-wasi/disable-all-logging", "log/release_max_level_off"]
headless = []
headless-minimal = ["headless", "disable-all-logging", "wasi"]
tracing = [ "dep:tracing", "tracing-subscriber" ]

# Optional
enable-serde = [
76 changes: 18 additions & 58 deletions lib/cli/src/logging.rs
Original file line number Diff line number Diff line change
@@ -1,68 +1,28 @@
//! Logging functions for the debug feature.
use crate::utils::wasmer_should_print_color;
use anyhow::Result;
use fern::colors::{Color, ColoredLevelConfig};
use std::time;

/// The debug level
pub type DebugLevel = log::LevelFilter;

/// Subroutine to instantiate the loggers
#[cfg(any(feature = "tracing", feature = "debug"))]
pub fn set_up_logging(verbose: u8) -> Result<(), String> {
let colors_line = ColoredLevelConfig::new()
.error(Color::Red)
.warn(Color::Yellow)
.trace(Color::BrightBlack);
let should_color = wasmer_should_print_color();
use tracing_subscriber::prelude::*;
use tracing_subscriber::{fmt, EnvFilter};

let colors_level = colors_line.info(Color::Green);
let level = match verbose {
1 => DebugLevel::Debug,
_ => DebugLevel::Trace,
};
let dispatch = fern::Dispatch::new()
.level(level)
.chain({
let base = if should_color {
fern::Dispatch::new().format(move |out, message, record| {
let time = time::SystemTime::now().duration_since(time::UNIX_EPOCH).expect("Can't get time");
out.finish(format_args!(
"{color_line}[{seconds}.{millis} {level} {target}{color_line}]{ansi_close} {message}",
color_line = format_args!(
"\x1B[{}m",
colors_line.get_color(&record.level()).to_fg_str()
),
seconds = time.as_secs(),
millis = time.subsec_millis(),
level = colors_level.color(record.level()),
target = record.target(),
ansi_close = "\x1B[0m",
message = message,
));
})
} else {
// default formatter without color
fern::Dispatch::new().format(move |out, message, record| {
let time = time::SystemTime::now().duration_since(time::UNIX_EPOCH).expect("Can't get time");
out.finish(format_args!(
"[{seconds}.{millis} {level} {target}] {message}",
seconds = time.as_secs(),
millis = time.subsec_millis(),
level = record.level(),
target = record.target(),
message = message,
));
})
};
let fmt_layer = fmt::layer()
.with_target(false)
.with_span_events(fmt::format::FmtSpan::CLOSE)
.with_thread_ids(true)
.compact();

base
.filter(|metadata| {
metadata.target().starts_with("wasmer")
})
.chain(std::io::stdout())
});
let filter_layer = EnvFilter::try_from_default_env()
.or_else(|_| match verbose {
1 => EnvFilter::try_new("debug"),
_ => EnvFilter::try_new("trace"),
})
.unwrap();

dispatch.apply().map_err(|e| format!("{}", e))?;
tracing_subscriber::registry()
.with(filter_layer)
.with(fmt_layer)
.init();

Ok(())
}
20 changes: 10 additions & 10 deletions lib/wasi-types/src/wasi/bindings.rs
Original file line number Diff line number Diff line change
@@ -417,11 +417,7 @@ impl Errno {
}
impl core::fmt::Debug for Errno {
fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result {
f.debug_struct("Errno")
.field("code", &(*self as i32))
.field("name", &self.name())
.field("message", &self.message())
.finish()
write!(f, "Errno::{}", &self.name())
}
}
impl core::fmt::Display for Errno {
@@ -528,11 +524,7 @@ impl BusErrno {
}
impl core::fmt::Debug for BusErrno {
fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result {
f.debug_struct("BusErrno")
.field("code", &(*self as i32))
.field("name", &self.name())
.field("message", &self.message())
.finish()
write!(f, "BusErrno::{}", &self.name())
}
}
impl core::fmt::Display for BusErrno {
@@ -2166,6 +2158,14 @@ impl core::fmt::Debug for Bool {
}
}
}
impl core::fmt::Display for Bool {
fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result {
match self {
Bool::False => write!(f, "false"),
Bool::True => write!(f, "true"),
}
}
}
#[repr(C)]
#[derive(Copy, Clone)]
pub struct OptionTimestamp {
2 changes: 1 addition & 1 deletion lib/wasi/Cargo.toml
Original file line number Diff line number Diff line change
@@ -13,7 +13,7 @@ edition = "2018"
[dependencies]
cfg-if = "1.0"
thiserror = "1"
tracing = "0.1"
tracing = { version = "0.1" }
getrandom = "0.2"
wasmer-wasi-types = { path = "../wasi-types", version = "=3.2.0-alpha.1" }
wasmer-types = { path = "../types", version = "=3.2.0-alpha.1", default-features = false }
8 changes: 7 additions & 1 deletion lib/wasi/src/os/task/process.rs
Original file line number Diff line number Diff line change
@@ -28,7 +28,7 @@ use super::{
};

/// Represents the ID of a sub-process
#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
#[derive(Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
pub struct WasiProcessId(u32);

impl WasiProcessId {
@@ -67,6 +67,12 @@ impl std::fmt::Display for WasiProcessId {
}
}

impl std::fmt::Debug for WasiProcessId {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
write!(f, "{}", self.0)
}
}

/// Represents a process running within the compute state
// TODO: fields should be private and only accessed via methods.
#[derive(Debug, Clone)]
8 changes: 7 additions & 1 deletion lib/wasi/src/os/task/thread.rs
Original file line number Diff line number Diff line change
@@ -22,7 +22,7 @@ use super::{
};

/// Represents the ID of a WASI thread
#[derive(Debug, Default, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
#[derive(Default, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
pub struct WasiThreadId(u32);

impl WasiThreadId {
@@ -67,6 +67,12 @@ impl std::fmt::Display for WasiThreadId {
}
}

impl std::fmt::Debug for WasiThreadId {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
write!(f, "{}", self.0)
}
}

/// Represents a linked list of stack snapshots
#[derive(Debug, Clone)]
struct ThreadSnapshot {
12 changes: 6 additions & 6 deletions lib/wasi/src/syscalls/legacy/snapshot0.rs
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
use tracing::{field, instrument, trace_span};
use wasmer::{AsStoreMut, FunctionEnvMut, WasmPtr};
use wasmer_wasi_types::wasi::{
Errno, Event, EventFdReadwrite, Eventrwflags, Eventtype, Fd, Filesize, Filestat, Filetype,
@@ -20,6 +21,7 @@ use crate::{
/// WARNING: this function involves saving, clobbering, and restoring unrelated
/// Wasm memory. If the memory clobbered by the current syscall is also used by
/// that syscall, then it may break.
#[instrument(level = "debug", skip_all, ret)]
pub fn fd_filestat_get(
mut ctx: FunctionEnvMut<WasiEnv>,
fd: Fd,
@@ -72,6 +74,7 @@ pub fn fd_filestat_get(

/// Wrapper around `syscalls::path_filestat_get` with extra logic to handle the size
/// difference of `wasi_filestat_t`
#[instrument(level = "debug", skip_all, ret)]
pub fn path_filestat_get(
mut ctx: FunctionEnvMut<WasiEnv>,
fd: Fd,
@@ -115,6 +118,7 @@ pub fn path_filestat_get(

/// Wrapper around `syscalls::fd_seek` with extra logic to remap the values
/// of `Whence`
#[instrument(level = "debug", skip_all, ret)]
pub fn fd_seek(
ctx: FunctionEnvMut<WasiEnv>,
fd: Fd,
@@ -132,6 +136,7 @@ pub fn fd_seek(

/// Wrapper around `syscalls::poll_oneoff` with extra logic to add the removed
/// userdata field back
#[instrument(level = "trace", skip_all, fields(timeout_ns = field::Empty, fd_guards = field::Empty, seen = field::Empty), ret, err)]
pub fn poll_oneoff(
mut ctx: FunctionEnvMut<WasiEnv>,
in_: WasmPtr<Snapshot0Subscription, Memory32>,
@@ -157,12 +162,7 @@ pub fn poll_oneoff(
let triggered_events = match triggered_events {
Ok(a) => a,
Err(err) => {
tracing::trace!(
"wasi[{}:{}]::poll_oneoff0 errno={}",
ctx.data().pid(),
ctx.data().tid(),
err
);
tracing::trace!(err = err as u16);
return Ok(err);
}
};
12 changes: 2 additions & 10 deletions lib/wasi/src/syscalls/mod.rs
Original file line number Diff line number Diff line change
@@ -21,6 +21,7 @@ pub mod wasix;

use bytes::{Buf, BufMut};
use futures::Future;
use tracing::instrument;
pub use wasi::*;
pub use wasix::*;

@@ -664,7 +665,6 @@ pub(crate) fn write_buffer_array<M: MemorySize>(

let mut current_buffer_offset = 0usize;
for ((i, sub_buffer), ptr) in from.iter().enumerate().zip(ptrs.iter()) {
trace!("ptr: {:?}, subbuffer: {:?}", ptr, sub_buffer);
let mut buf_offset = buffer.offset();
buf_offset += wasi_try!(to_offset::<M>(current_buffer_offset));
let new_ptr = WasmPtr::new(buf_offset);
@@ -935,22 +935,14 @@ where
Ok(Errno::Success)
}

#[instrument(level = "debug", skip_all, fields(memory_stack_len = memory_stack.len(), rewind_stack_len = rewind_stack.len(), store_data_len = store_data.len()))]
#[must_use = "the action must be passed to the call loop"]
pub(crate) fn rewind<M: MemorySize>(
mut ctx: FunctionEnvMut<'_, WasiEnv>,
memory_stack: Bytes,
rewind_stack: Bytes,
store_data: Bytes,
) -> Errno {
trace!(
"wasi[{}:{}]::rewinding (memory_stack_size={}, rewind_size={}, store_data={})",
ctx.data().pid(),
ctx.data().tid(),
memory_stack.len(),
rewind_stack.len(),
store_data.len()
);

// Store the memory stack so that it can be restored later
super::REWIND.with(|cell| cell.replace(Some(memory_stack)));

4 changes: 2 additions & 2 deletions lib/wasi/src/syscalls/wasi/args_get.rs
Original file line number Diff line number Diff line change
@@ -10,12 +10,12 @@ use crate::syscalls::*;
/// - `char *argv_buf`
/// A pointer to a buffer to write the argument string data.
///
#[instrument(level = "debug", skip_all, ret)]
pub fn args_get<M: MemorySize>(
mut ctx: FunctionEnvMut<'_, WasiEnv>,
argv: WasmPtr<WasmPtr<u8, M>, M>,
argv_buf: WasmPtr<u8, M>,
) -> Errno {
debug!("wasi[{}:{}]::args_get", ctx.data().pid(), ctx.data().tid());
let env = ctx.data();
let (memory, mut state) = env.get_memory_and_wasi_state(&ctx, 0);

@@ -27,7 +27,7 @@ pub fn args_get<M: MemorySize>(
let result = write_buffer_array(&memory, &args, argv, argv_buf);

debug!(
"=> args:\n{}",
"args:\n{}",
state
.args
.iter()
Loading