Merge pull request #1796 from bytecodealliance/pch/wiggle_tracing

wiggle: switch logging to use `tracing` crate
This commit is contained in:
Pat Hickey
2020-06-04 09:44:23 -07:00
committed by GitHub
17 changed files with 456 additions and 79 deletions

137
Cargo.lock generated
View File

@@ -252,6 +252,17 @@ version = "0.1.10"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "4785bdd1c96b2a846b2bd7cc02e86b6b3dbf14e7e53446c4f54c92a361040822"
[[package]]
name = "chrono"
version = "0.4.11"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "80094f509cf8b5ae86a4966a39b3ff66cd7e2a3e594accec3743ff3fabeab5b2"
dependencies = [
"num-integer",
"num-traits",
"time",
]
[[package]]
name = "clap"
version = "2.33.1"
@@ -1132,6 +1143,15 @@ dependencies = [
"libc",
]
[[package]]
name = "matchers"
version = "0.0.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1"
dependencies = [
"regex-automata",
]
[[package]]
name = "maybe-uninit"
version = "2.0.0"
@@ -1169,6 +1189,16 @@ version = "0.2.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "0debeb9fcf88823ea64d64e4a815ab1643f33127d995978e099942ce38f25238"
[[package]]
name = "num-integer"
version = "0.1.42"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "3f6ea62e9d81a77cd3ee9a2a5b9b609447857f3d358704331e4ef39eb247fcba"
dependencies = [
"autocfg 1.0.0",
"num-traits",
]
[[package]]
name = "num-traits"
version = "0.2.11"
@@ -1657,6 +1687,16 @@ dependencies = [
"thread_local",
]
[[package]]
name = "regex-automata"
version = "0.1.9"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ae1ded71d66a4a97f5e961fd0cb25a5f366a42a41570d16a763a69c092c26ae4"
dependencies = [
"byteorder",
"regex-syntax",
]
[[package]]
name = "regex-syntax"
version = "0.6.18"
@@ -1835,6 +1875,15 @@ dependencies = [
"opaque-debug",
]
[[package]]
name = "sharded-slab"
version = "0.0.9"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "06d5a3f5166fb5b42a5439f2eee8b9de149e235961e3eb21c5808fc3ea17ff3e"
dependencies = [
"lazy_static",
]
[[package]]
name = "smallvec"
version = "1.4.0"
@@ -2026,6 +2075,16 @@ dependencies = [
"lazy_static",
]
[[package]]
name = "time"
version = "0.1.43"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ca8a50ef2360fbd1eeb0ecd46795a87a19024eb4b53c5dc916ca1fd95fe62438"
dependencies = [
"libc",
"winapi",
]
[[package]]
name = "toml"
version = "0.5.6"
@@ -2035,6 +2094,79 @@ dependencies = [
"serde",
]
[[package]]
name = "tracing"
version = "0.1.15"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "a41f40ed0e162c911ac6fcb53ecdc8134c46905fdbbae8c50add462a538b495f"
dependencies = [
"cfg-if",
"log",
"tracing-attributes",
"tracing-core",
]
[[package]]
name = "tracing-attributes"
version = "0.1.8"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "99bbad0de3fd923c9c3232ead88510b783e5a4d16a6154adffa3d53308de984c"
dependencies = [
"proc-macro2",
"quote",
"syn",
]
[[package]]
name = "tracing-core"
version = "0.1.10"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "0aa83a9a47081cd522c09c81b31aec2c9273424976f922ad61c053b58350b715"
dependencies = [
"lazy_static",
]
[[package]]
name = "tracing-log"
version = "0.1.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "5e0f8c7178e13481ff6765bd169b33e8d554c5d2bbede5e32c356194be02b9b9"
dependencies = [
"lazy_static",
"log",
"tracing-core",
]
[[package]]
name = "tracing-serde"
version = "0.1.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "b6ccba2f8f16e0ed268fc765d9b7ff22e965e7185d32f8f1ec8294fe17d86e79"
dependencies = [
"serde",
"tracing-core",
]
[[package]]
name = "tracing-subscriber"
version = "0.2.5"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "1d53c40489aa69c9aed21ff483f26886ca8403df33bdc2d2f87c60c1617826d2"
dependencies = [
"ansi_term",
"chrono",
"lazy_static",
"matchers",
"regex",
"serde",
"serde_json",
"sharded-slab",
"smallvec",
"tracing-core",
"tracing-log",
"tracing-serde",
]
[[package]]
name = "traitobject"
version = "0.1.0"
@@ -2480,6 +2612,7 @@ version = "0.17.0"
dependencies = [
"proptest",
"thiserror",
"tracing",
"wiggle-macro",
"wiggle-test",
"witx",
@@ -2512,7 +2645,11 @@ dependencies = [
name = "wiggle-test"
version = "0.17.0"
dependencies = [
"env_logger",
"proptest",
"thiserror",
"tracing",
"tracing-subscriber",
"wiggle",
]

View File

@@ -41,10 +41,10 @@ maintenance = { status = "actively-developed" }
[features]
default = ["trace_log"]
# This feature enables `log::trace` calls in syscalls shims, in effect
# emulating something like `strace`. This feature is an opt-out and hence
# enabled by 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" ]
# 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"]

View File

@@ -14,6 +14,7 @@ include = ["src/**/*", "LICENSE"]
thiserror = "1"
witx = { path = "../wasi-common/WASI/tools/witx", version = "0.8.5", optional = true }
wiggle-macro = { path = "macro", version = "0.17.0" }
tracing = "0.1.15"
[badges]
maintenance = { status = "actively-developed" }
@@ -23,13 +24,16 @@ wiggle-test = { path = "test-helpers" }
proptest = "0.9"
[features]
# These features have no effect on the users of this crate. They are only
# necessary for testing.
# The wiggle proc-macro emits some code (inside `pub mod metadata`) guarded
# by the `wiggle_metadata` feature flag. We use this feature flag so that
# users of wiggle are not forced to take a direct dependency on the `witx`
# crate unless they want it.
wiggle_metadata = ['witx', "wiggle-macro/wiggle_metadata"]
# In order to test that the contents of this metadata module meet
# expectations, we must have this feature enabled for the crate by default.
default = ["wiggle_metadata"]
# The `tracing` crate can use the `log` ecosystem of backends with this
# non-default feature. We don't need to provide this by default, but its
# useful for users that don't want to use `tracing-subscriber` to get
# the logs out of wiggle-generated libraries.
tracing_log = [ "tracing/log" ]
default = ["wiggle_metadata" ]

View File

@@ -27,23 +27,35 @@ pub enum ConfigField {
Error(ErrorConf),
}
impl ConfigField {
pub fn parse_pair(ident: &str, value: ParseStream, err_loc: Span) -> Result<Self> {
match ident {
"witx" => Ok(ConfigField::Witx(WitxConf::Paths(value.parse()?))),
"witx_literal" => Ok(ConfigField::Witx(WitxConf::Literal(value.parse()?))),
"ctx" => Ok(ConfigField::Ctx(value.parse()?)),
"errors" => Ok(ConfigField::Error(value.parse()?)),
_ => Err(Error::new(err_loc, "expected `witx`, `ctx`, or `errors`")),
}
}
mod kw {
syn::custom_keyword!(witx);
syn::custom_keyword!(witx_literal);
syn::custom_keyword!(ctx);
syn::custom_keyword!(errors);
}
impl Parse for ConfigField {
fn parse(input: ParseStream) -> Result<Self> {
let id: Ident = input.parse()?;
let _colon: Token![:] = input.parse()?;
Self::parse_pair(id.to_string().as_ref(), input, id.span())
let lookahead = input.lookahead1();
if lookahead.peek(kw::witx) {
input.parse::<kw::witx>()?;
input.parse::<Token![:]>()?;
Ok(ConfigField::Witx(WitxConf::Paths(input.parse()?)))
} else if lookahead.peek(kw::witx_literal) {
input.parse::<kw::witx_literal>()?;
input.parse::<Token![:]>()?;
Ok(ConfigField::Witx(WitxConf::Literal(input.parse()?)))
} else if lookahead.peek(kw::ctx) {
input.parse::<kw::ctx>()?;
input.parse::<Token![:]>()?;
Ok(ConfigField::Ctx(input.parse()?))
} else if lookahead.peek(kw::errors) {
input.parse::<kw::errors>()?;
input.parse::<Token![:]>()?;
Ok(ConfigField::Error(input.parse()?))
} else {
Err(lookahead.error())
}
}
}

View File

@@ -11,6 +11,9 @@ pub struct ErrorTransform {
}
impl ErrorTransform {
pub fn empty() -> Self {
Self { m: Vec::new() }
}
pub fn new(conf: &ErrorConf, doc: &Document) -> Result<Self, Error> {
let mut richtype_identifiers = HashMap::new();
let m = conf.iter().map(|(ident, field)|

View File

@@ -5,11 +5,12 @@ use crate::error_transform::ErrorTransform;
use crate::lifetimes::anon_lifetime;
use crate::module_trait::passed_by_reference;
use crate::names::Names;
use crate::types::WiggleType;
pub fn define_func(
names: &Names,
module: &witx::Module,
func: &witx::InterfaceFunc,
trait_name: TokenStream,
errxform: &ErrorTransform,
) -> TokenStream {
let funcname = func.name.as_str();
@@ -49,19 +50,20 @@ pub fn define_func(
let ret_err = coretype
.ret
.map(|ret| {
let name = ret.param.name.as_str();
let name = names.func_param(&ret.param.name);
let conversion = if let Some(user_err) = errxform.for_abi_error(&ret.param.tref) {
let method = names.user_error_conversion_method(&user_err);
quote!(#abi_ret::from(UserErrorConversion::#method(ctx, e)))
quote!(UserErrorConversion::#method(ctx, e))
} else {
quote!(#abi_ret::from(e))
quote!(e)
};
quote! {
#[cfg(feature = "trace_log")]
{
log::trace!(" | {}={:?}", #name, e);
}
return #conversion;
let e = #conversion;
#rt::tracing::event!(
#rt::tracing::Level::TRACE,
#name = #rt::tracing::field::debug(&e),
);
return #abi_ret::from(e);
}
})
.unwrap_or_else(|| quote!(()));
@@ -76,7 +78,7 @@ pub fn define_func(
let err_method = names.guest_error_conversion_method(&tref);
quote! {
let e = #rt::GuestError::InFunc { funcname: #funcname, location: #location, err: Box::new(e.into()) };
let err: #err_typename = GuestErrorConversion::#err_method(ctx, e); // XXX replace with conversion method on trait!
let err: #err_typename = GuestErrorConversion::#err_method(ctx, e);
return #abi_ret::from(err);
}
} else {
@@ -99,6 +101,23 @@ pub fn define_func(
}
});
let log_marshalled_args = if func.params.len() > 0 {
let rt = names.runtime_mod();
let args = func.params.iter().map(|param| {
let name = names.func_param(&param.name);
if param.impls_display() {
quote!( #name = #rt::tracing::field::display(&#name) )
} else {
quote!( #name = #rt::tracing::field::debug(&#name) )
}
});
quote! {
#rt::tracing::event!(#rt::tracing::Level::TRACE, #(#args),*);
}
} else {
quote!()
};
let (trait_rets, trait_bindings) = if func.results.len() < 2 {
(quote!({}), quote!(_))
} else {
@@ -109,29 +128,16 @@ pub fn define_func(
.map(|result| names.func_param(&result.name))
.collect();
let bindings = quote!((#(#trait_rets),*));
let names: Vec<_> = func
.results
.iter()
.skip(1)
.map(|result| {
let name = names.func_param(&result.name);
let fmt = match &*result.tref.type_() {
witx::Type::Builtin(_)
| witx::Type::Enum(_)
| witx::Type::Flags(_)
| witx::Type::Handle(_)
| witx::Type::Int(_) => "{}",
_ => "{:?}",
};
format!("{}={}", name.to_string(), fmt)
})
.collect();
let trace_fmt = format!(" | result=({})", names.join(","));
let rets = quote! {
#[cfg(feature = "trace_log")]
{
log::trace!(#trace_fmt, #(#trait_rets),*);
let trace_rets = func.results.iter().skip(1).map(|result| {
let name = names.func_param(&result.name);
if result.tref.impls_display() {
quote!(#name = #rt::tracing::field::display(&#name))
} else {
quote!(#name = #rt::tracing::field::debug(&#name))
}
});
let rets = quote! {
#rt::tracing::event!(#rt::tracing::Level::TRACE, #(#trace_rets),*);
(#(#trait_rets),*)
};
(rets, bindings)
@@ -151,37 +157,32 @@ pub fn define_func(
let err_typename = names.type_ref(&err_type, anon_lifetime());
quote! {
let success:#err_typename = #rt::GuestErrorType::success();
#[cfg(feature = "trace_log")]
{
log::trace!(" | errno={}", success);
}
#rt::tracing::event!(
#rt::tracing::Level::TRACE,
success=#rt::tracing::field::display(&success)
);
#abi_ret::from(success)
}
} else {
quote!()
};
let (placeholders, args): (Vec<_>, Vec<_>) = func
.params
.iter()
.map(|param| {
let name = names.func_param(&param.name);
let fmt = if passed_by_reference(&*param.tref.type_()) {
"{:?}"
} else {
"{}"
};
(format!("{}={}", name.to_string(), fmt), quote!(#name))
})
.unzip();
let trace_fmt = format!("{}({})", ident.to_string(), placeholders.join(","));
let trait_name = names.trait_name(&module.name);
let mod_name = &module.name.as_str();
let func_name = &func.name.as_str();
quote!(pub fn #ident(#abi_args) -> #abi_ret {
let _span = #rt::tracing::span!(
#rt::tracing::Level::TRACE,
"wiggle abi",
module = #mod_name,
function = #func_name
);
let _enter = _span.enter();
#(#marshal_args)*
#(#marshal_rets_pre)*
#[cfg(feature = "trace_log")]
{
log::trace!(#trace_fmt, #(#args),*);
}
#log_marshalled_args
let #trait_bindings = match #trait_name::#ident(ctx, #(#trait_args),*) {
Ok(#trait_bindings) => { #trait_rets },
Err(e) => { #ret_err },

View File

@@ -49,10 +49,9 @@ pub fn generate(doc: &witx::Document, names: &Names, errs: &ErrorTransform) -> T
};
let modules = doc.modules().map(|module| {
let modname = names.module(&module.name);
let trait_name = names.trait_name(&module.name);
let fs = module
.funcs()
.map(|f| define_func(&names, &f, quote!(#trait_name), &errs));
.map(|f| define_func(&names, &module, &f, &errs));
let modtrait = define_module_trait(&names, &module, &errs);
let ctx_type = names.ctx_type();
quote!(

View File

@@ -112,3 +112,9 @@ pub(super) fn define_enum(names: &Names, name: &witx::Id, e: &witx::EnumDatatype
}
}
}
impl super::WiggleType for witx::EnumDatatype {
fn impls_display(&self) -> bool {
true
}
}

View File

@@ -180,3 +180,9 @@ pub(super) fn define_flags(names: &Names, name: &witx::Id, f: &witx::FlagsDataty
}
}
impl super::WiggleType for witx::FlagsDatatype {
fn impls_display(&self) -> bool {
true
}
}

View File

@@ -82,3 +82,9 @@ pub(super) fn define_handle(
}
}
impl super::WiggleType for witx::HandleDatatype {
fn impls_display(&self) -> bool {
true
}
}

View File

@@ -92,3 +92,9 @@ pub(super) fn define_int(names: &Names, name: &witx::Id, i: &witx::IntDatatype)
}
}
impl super::WiggleType for witx::IntDatatype {
fn impls_display(&self) -> bool {
true
}
}

View File

@@ -91,3 +91,56 @@ fn atom_token(atom: witx::AtomType) -> TokenStream {
witx::AtomType::F64 => quote!(f64),
}
}
pub trait WiggleType {
fn impls_display(&self) -> bool;
}
impl WiggleType for witx::TypeRef {
fn impls_display(&self) -> bool {
match self {
witx::TypeRef::Name(alias_to) => (&*alias_to).impls_display(),
witx::TypeRef::Value(v) => (&*v).impls_display(),
}
}
}
impl WiggleType for witx::NamedType {
fn impls_display(&self) -> bool {
self.tref.impls_display()
}
}
impl WiggleType for witx::Type {
fn impls_display(&self) -> bool {
match self {
witx::Type::Enum(x) => x.impls_display(),
witx::Type::Int(x) => x.impls_display(),
witx::Type::Flags(x) => x.impls_display(),
witx::Type::Struct(x) => x.impls_display(),
witx::Type::Union(x) => x.impls_display(),
witx::Type::Handle(x) => x.impls_display(),
witx::Type::Builtin(x) => x.impls_display(),
witx::Type::Pointer { .. }
| witx::Type::ConstPointer { .. }
| witx::Type::Array { .. } => false,
}
}
}
impl WiggleType for witx::BuiltinType {
fn impls_display(&self) -> bool {
true
}
}
impl WiggleType for witx::InterfaceFuncParam {
fn impls_display(&self) -> bool {
match &*self.tref.type_() {
witx::Type::Struct { .. }
| witx::Type::Union { .. }
| witx::Type::Builtin(witx::BuiltinType::String { .. }) => false,
_ => self.tref.impls_display(),
}
}
}

View File

@@ -133,3 +133,9 @@ pub(super) fn define_struct(
#transparent
}
}
impl super::WiggleType for witx::StructDatatype {
fn impls_display(&self) -> bool {
false
}
}

View File

@@ -108,3 +108,9 @@ pub(super) fn define_union(names: &Names, name: &witx::Id, u: &witx::UnionDataty
}
}
}
impl super::WiggleType for witx::UnionDatatype {
fn impls_display(&self) -> bool {
false
}
}

View File

@@ -16,6 +16,8 @@ mod error;
mod guest_type;
mod region;
pub extern crate tracing;
pub use borrow::BorrowChecker;
use borrow::BorrowHandle;
pub use error::GuestError;

View File

@@ -12,7 +12,14 @@ include = ["src/**/*", "LICENSE"]
[dependencies]
proptest = "0.9"
wiggle = { path = ".." }
wiggle = { path = "..", features = ["tracing_log"] }
[dev-dependencies]
thiserror = "1.0"
tracing = "0.1.14"
tracing-subscriber = "0.2.4"
env_logger = "0.7"
[badges]
maintenance = { status = "actively-developed" }

View File

@@ -0,0 +1,123 @@
use wiggle_test::{impl_errno, HostMemory, WasiCtx};
/// The `errors` argument to the wiggle gives us a hook to map a rich error
/// type like this one (typical of wiggle use cases in wasi-common and beyond)
/// down to the flat error enums that witx can specify.
#[derive(Debug, thiserror::Error)]
pub enum RichError {
#[error("Invalid argument: {0}")]
InvalidArg(String),
#[error("Won't cross picket line: {0}")]
PicketLine(String),
}
// Define an errno with variants corresponding to RichError. Use it in a
// trivial function.
wiggle::from_witx!({
witx_literal: "
(typename $errno (enum u8 $ok $invalid_arg $picket_line))
(typename $s (struct (field $f1 (@witx usize)) (field $f2 (@witx pointer u8))))
(typename $t (struct (field $f1 u32) (field $f2 f32)))
(module $one_error_conversion
(@interface func (export \"foo\")
(param $strike u32)
(param $s $s)
(result $err $errno)
(result $t $t)))
",
ctx: WasiCtx,
errors: { errno => RichError },
});
// The impl of GuestErrorConversion works just like in every other test where
// we have a single error type with witx `$errno` with the success called `$ok`
impl_errno!(types::Errno, types::GuestErrorConversion);
/// When the `errors` mapping in witx is non-empty, we need to impl the
/// types::UserErrorConversion trait that wiggle generates from that mapping.
impl<'a> types::UserErrorConversion for WasiCtx<'a> {
fn errno_from_rich_error(&self, e: RichError) -> types::Errno {
wiggle::tracing::debug!(
rich_error = wiggle::tracing::field::debug(&e),
"error conversion"
);
// WasiCtx can collect a Vec<String> log so we can test this. We're
// logging the Display impl that `thiserror::Error` provides us.
self.log.borrow_mut().push(e.to_string());
// Then do the trivial mapping down to the flat enum.
match e {
RichError::InvalidArg { .. } => types::Errno::InvalidArg,
RichError::PicketLine { .. } => types::Errno::PicketLine,
}
}
}
impl<'a> one_error_conversion::OneErrorConversion for WasiCtx<'a> {
fn foo(&self, strike: u32, _s: &types::S) -> Result<types::T, RichError> {
// We use the argument to this function to exercise all of the
// possible error cases we could hit here
match strike {
0 => Ok(types::T {
f1: 123,
f2: 456.78,
}),
1 => Err(RichError::PicketLine(format!("I'm not a scab"))),
_ => Err(RichError::InvalidArg(format!("out-of-bounds: {}", strike))),
}
}
}
fn main() {
if std::env::var("RUST_LOG").is_err() {
// with no RUST_LOG env variable: use the tracing subscriber.
let subscriber = tracing_subscriber::fmt()
// all spans/events with a level equal to or higher than TRACE (e.g, trace, debug, info, warn, etc.)
// will be written to stdout.
.with_max_level(tracing::Level::TRACE)
// builds the subscriber.
.finish();
tracing::subscriber::set_global_default(subscriber).expect("set global tracing subscriber");
} else {
// with RUST_LOG set: use the env_logger backend to tracing.
env_logger::init();
}
let ctx = WasiCtx::new();
let host_memory = HostMemory::new();
// Exercise each of the branches in `foo`.
// Start with the success case:
let r0 = one_error_conversion::foo(&ctx, &host_memory, 0, 0, 8);
assert_eq!(
r0,
i32::from(types::Errno::Ok),
"Expected return value for strike=0"
);
assert!(ctx.log.borrow().is_empty(), "No error log for strike=0");
// First error case:
let r1 = one_error_conversion::foo(&ctx, &host_memory, 1, 0, 8);
assert_eq!(
r1,
i32::from(types::Errno::PicketLine),
"Expected return value for strike=1"
);
assert_eq!(
ctx.log.borrow_mut().pop().expect("one log entry"),
"Won't cross picket line: I'm not a scab",
"Expected log entry for strike=1",
);
// Second error case:
let r2 = one_error_conversion::foo(&ctx, &host_memory, 2, 0, 8);
assert_eq!(
r2,
i32::from(types::Errno::InvalidArg),
"Expected return value for strike=2"
);
assert_eq!(
ctx.log.borrow_mut().pop().expect("one log entry"),
"Invalid argument: out-of-bounds: 2",
"Expected log entry for strike=2",
);
}