T0b1/wasmtime
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

replace all uses of log with tracing

Browse Source
This commit is contained in:
Pat Hickey
2020-06-02 12:24:28 -07:00
parent f89fc0ac57
commit 02c0c68ed2
16 changed files with 285 additions and 152 deletions
Download Patch File Download Diff File Expand all files Collapse all files

1
Cargo.lock generated
View File

@@ -2623,6 +2623,7 @@ version = "0.17.0"
dependencies = [
"proptest",
"thiserror",
"tracing",
"wiggle-macro",
"wiggle-test",
"witx",

12
crates/wiggle/Cargo.toml
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_crate = { version = "0.1.14", optional = true, package = "tracing" }
[badges]
maintenance = { status = "actively-developed" }
@@ -23,13 +24,14 @@ 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 wiggle proc-macro emits code which may transitively depend on the
# `tracing` crate, via `wiggle::tracing`. When this feature is not enabled,
# a no-op equivelant to the tracing macros is provided instead.
tracing = [ "tracing_crate" ]
default = ["wiggle_metadata", "tracing"]

49
crates/wiggle/generate/src/config.rs
View File

@@ -18,7 +18,6 @@ pub struct Config {
pub witx: WitxConf,
pub ctx: CtxConf,
pub errors: ErrorConf,
pub logging: LoggingConf,
}
#[derive(Debug, Clone)]
@@ -26,17 +25,13 @@ pub enum ConfigField {
Witx(WitxConf),
Ctx(CtxConf),
Error(ErrorConf),
Logging(LoggingConf),
}
mod kw {
syn::custom_keyword!(witx);
syn::custom_keyword!(witx_literal);
syn::custom_keyword!(ctx);
syn::custom_keyword!(logging);
syn::custom_keyword!(errors);
syn::custom_keyword!(log);
syn::custom_keyword!(tracing);
}
impl Parse for ConfigField {
@@ -54,10 +49,6 @@ impl Parse for ConfigField {
input.parse::<kw::ctx>()?;
input.parse::<Token![:]>()?;
Ok(ConfigField::Ctx(input.parse()?))
} else if lookahead.peek(kw::logging) {
input.parse::<kw::logging>()?;
input.parse::<Token![:]>()?;
Ok(ConfigField::Logging(input.parse()?))
} else if lookahead.peek(kw::errors) {
input.parse::<kw::errors>()?;
input.parse::<Token![:]>()?;
@@ -73,7 +64,6 @@ impl Config {
let mut witx = None;
let mut ctx = None;
let mut errors = None;
let mut logging = None;
for f in fields {
match f {
ConfigField::Witx(c) => {
@@ -94,12 +84,6 @@ impl Config {
}
errors = Some(c);
}
ConfigField::Logging(c) => {
if logging.is_some() {
return Err(Error::new(err_loc, "duplicate `logging` field"));
}
logging = Some(c);
}
}
}
Ok(Config {
@@ -110,7 +94,6 @@ impl Config {
.take()
.ok_or_else(|| Error::new(err_loc, "`ctx` field required"))?,
errors: errors.take().unwrap_or_default(),
logging: logging.take().unwrap_or_default(),
})
}
@@ -319,35 +302,3 @@ impl Parse for ErrorConfField {
})
}
}
/// Configure logging statements in generated code
#[derive(Debug, Clone)]
pub enum LoggingConf {
Log { cfg_feature: Option<String> },
Tracing,
}
impl Default for LoggingConf {
fn default() -> Self {
// For compatibility with existing code. We should probably revise this later.
LoggingConf::Log {
cfg_feature: Some("trace_log".to_owned()),
}
}
}
impl Parse for LoggingConf {
fn parse(input: ParseStream) -> Result<Self> {
let lookahead = input.lookahead1();
if lookahead.peek(kw::log) {
input.parse::<kw::log>()?;
// TODO: syntax so the user can specify their own cfg_feature guard here.
Ok(LoggingConf::Log { cfg_feature: None })
} else if lookahead.peek(kw::tracing) {
input.parse::<kw::tracing>()?;
Ok(LoggingConf::Tracing)
} else {
Err(lookahead.error())
}
}
}

142
crates/wiggle/generate/src/funcs.rs
View File

@@ -1,18 +1,17 @@
use proc_macro2::TokenStream;
use quote::quote;
use crate::config::LoggingConf;
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,
logging: &LoggingConf,
) -> TokenStream {
let funcname = func.name.as_str();
@@ -51,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!(()));
@@ -78,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 {
@@ -101,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 {
@@ -111,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)
@@ -153,22 +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 log_args = logging.args(&func, names);
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)*
#log_args
#log_marshalled_args
let #trait_bindings = match #trait_name::#ident(ctx, #(#trait_args),*) {
Ok(#trait_bindings) => { #trait_rets },
Err(e) => { #ret_err },
@@ -323,51 +337,3 @@ where
_ => write_val_to_ptr,
}
}
impl LoggingConf {
fn args(&self, func: &witx::InterfaceFunc, names: &Names) -> TokenStream {
match self {
Self::Log { cfg_feature } => {
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!(
"{}({})",
names.func(&func.name).to_string(),
placeholders.join(",")
);
let trace_stmt = quote!(log::trace!(#trace_fmt, #(#args),*););
if let Some(feature) = cfg_feature {
quote! {
#[cfg(feature = #feature)]
{
#trace_stmt
}
}
} else {
trace_stmt
}
}
Self::Tracing => {
let args = func.params.iter().map(|param| {
let name = names.func_param(&param.name);
quote!( #name = #name )
});
let func_name = names.func(&func.name).to_string();
quote! {
tracing::debug!(function = #func_name, #(#args),*, "marshalled arguments");
}
}
}
}
}

12
crates/wiggle/generate/src/lib.rs
View File

@@ -11,19 +11,14 @@ use quote::quote;
use lifetimes::anon_lifetime;
pub use config::{Config, LoggingConf};
pub use config::Config;
pub use error_transform::{ErrorTransform, UserErrorType};
pub use funcs::define_func;
pub use module_trait::define_module_trait;
pub use names::Names;
pub use types::define_datatype;
pub fn generate(
doc: &witx::Document,
names: &Names,
errs: &ErrorTransform,
logging: &LoggingConf,
) -> TokenStream {
pub fn generate(doc: &witx::Document, names: &Names, errs: &ErrorTransform) -> TokenStream {
// TODO at some point config should grow more ability to configure name
// overrides.
let rt = names.runtime_mod();
@@ -54,10 +49,9 @@ pub fn generate(
};
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, logging));
.map(|f| define_func(&names, &module, &f, &errs));
let modtrait = define_module_trait(&names, &module, &errs);
let ctx_type = names.ctx_type();
quote!(

6
crates/wiggle/generate/src/types/enum.rs
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
}
}

6
crates/wiggle/generate/src/types/flags.rs
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
}
}

6
crates/wiggle/generate/src/types/handle.rs
View File

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

6
crates/wiggle/generate/src/types/int.rs
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
}
}

53
crates/wiggle/generate/src/types/mod.rs
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(),
}
}
}

6
crates/wiggle/generate/src/types/struct.rs
View File

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

6
crates/wiggle/generate/src/types/union.rs
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
}
}

2
crates/wiggle/macro/src/lib.rs
View File

@@ -101,7 +101,7 @@ pub fn from_witx(args: TokenStream) -> TokenStream {
let error_transform = wiggle_generate::ErrorTransform::new(&config.errors, &doc)
.expect("validating error transform");
let code = wiggle_generate::generate(&doc, &names, &error_transform, &config.logging);
let code = wiggle_generate::generate(&doc, &names, &error_transform);
let metadata = if cfg!(feature = "wiggle_metadata") {
wiggle_generate::generate_metadata(&doc, &names)
} else {

1
crates/wiggle/src/lib.rs
View File

@@ -15,6 +15,7 @@ mod borrow;
mod error;
mod guest_type;
mod region;
pub mod tracing;
pub use borrow::BorrowChecker;
use borrow::BorrowHandle;

11
crates/wiggle/src/tracing.rs Normal file
View File

@@ -0,0 +1,11 @@
#[cfg(feature = "tracing")]
pub use tracing_crate::*;
#[cfg(not(feature = "tracing"))]
mod noop_tracing {
// TODO fill in rest of the noop interface
// idk how to do this because macro_rules! / #[macro_export] doesn't follow the usual module
// visibility rules.
}
#[cfg(not(feature = "tracing"))]
pub use noop_tracing::*;

118
crates/wiggle/test-helpers/examples/tracing.rs Normal file
View File

@@ -0,0 +1,118 @@
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() {
let subscriber = tracing_subscriber::fmt()
// all spans/events with a level higher than TRACE (e.g, debug, info, warn, etc.)
// will be written to stdout.
.with_max_level(tracing::Level::TRACE)
// builds the subscriber.
.finish();
tracing::subscriber::with_default(subscriber, || {
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",
);
});
}