From 70492f502a7066d515df7b4d9380d4773d9a4e5e Mon Sep 17 00:00:00 2001 From: Benjamin Kampmann Date: Thu, 23 Jul 2020 17:54:11 +0200 Subject: [PATCH] make tracing codecable --- Cargo.lock | 2 + primitives/tracing/Cargo.toml | 20 ++- primitives/tracing/src/proxy.rs | 272 +++++++++++++++++--------------- 3 files changed, 167 insertions(+), 127 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 0b0262d918ac1..03fea95a7794b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -8221,8 +8221,10 @@ name = "sp-tracing" version = "2.0.0-rc5" dependencies = [ "log", + "parity-scale-codec", "rental", "tracing", + "tracing-core", ] [[package]] diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index fc3d311298dde..5209542dd8eef 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -12,10 +12,26 @@ description = "Instrumentation primitives and macros for Substrate." targets = ["x86_64-unknown-linux-gnu"] [dependencies] -tracing = { version = "0.1.13", optional = true } +codec = { version = "1.3.1", package = "parity-scale-codec", optional = true, default-features = false} +tracing = { version = "0.1.13", optional = true, default-features = false } +tracing-core = { version = "0.1.11", optional = true, default-features = false } rental = { version = "0.5.5", optional = true } log = { version = "0.4.8", optional = true } [features] default = [ "std" ] -std = [ "tracing", "rental", "log" ] +with-tracing = [ + "tracing", + "tracing-core", + "codec", + "codec/derive", + "codec/full", +] +std = [ + "with-tracing", + "tracing/std", + "tracing-core/std", + "codec/std", + "rental", + "log" +] diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 270f57aaa69f0..7e33b27e144ff 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -14,152 +14,174 @@ // You should have received a copy of the GNU General Public License // along with Substrate. If not, see . +#![cfg_attr(not(feature = "std"), no_std)] //! Proxy to allow entering tracing spans from wasm. -//! -//! Use `enter_span` and `exit_span` to surround the code that you wish to trace -use rental; -use tracing::info_span; - -/// Used to identify a proxied WASM trace -pub const WASM_TRACE_IDENTIFIER: &'static str = "WASM_TRACE"; -/// Used to extract the real `target` from the associated values of the span -pub const WASM_TARGET_KEY: &'static str = "proxied_wasm_target"; -/// Used to extract the real `name` from the associated values of the span -pub const WASM_NAME_KEY: &'static str = "proxied_wasm_name"; - -const MAX_SPANS_LEN: usize = 1000; - -rental! { - pub mod rent_span { - #[rental] - pub struct SpanAndGuard { - span: Box, - guard: tracing::span::Entered<'span>, - } +use core::{ + default::Default, + fmt::Debug, +}; +use codec::{Encode, Decode}; +use tracing_core::{ + subscriber::Subscriber, + metadata::Metadata, + field::{Field, Visit}, + event::{Event}, + span::{ + Attributes, + Id, + Record, + }, + Level, +}; + +struct WasmProxySubscriber; +impl Subscriber for WasmProxySubscriber { + fn enabled(&self, metadata: &Metadata) -> bool { + todo!{} + // host_functions::tracing_enabled(metadata.into()) + } + fn record_follows_from(&self, span: &Id, follows: &Id) { + todo!{} + // host_functions::tracing_record_follows_from(span.into_u64(), follows.into_u64()) + } + fn new_span(&self, span: &Attributes) -> Id { + todo!{} + // Id::from_u64(host_functions::tracing_new_span(span.into()) + } + fn record(&self, span: &Id, values: &Record) { + todo!{} + // host_functions::tracing_record(span.into_u64(), value.into()) + } + fn event(&self, event: &Event) { + todo!{} + // host_functions::tracing_enter(event.into()) + } + fn enter(&self, span: &Id) { + todo!{} + // host_functions::tracing_enter(span.into_u64()) + } + fn exit(&self, span: &Id) { + todo!{} + // host_functions::tracing_exit(span.into_u64()) } } -/// Requires a tracing::Subscriber to process span traces, -/// this is available when running with client (and relevant cli params). -pub struct TracingProxy { - next_id: u64, - spans: Vec<(u64, rent_span::SpanAndGuard)>, +#[derive(Encode, Decode)] +pub enum FieldValue { + I64(i64), + U64(u64), + Bool(bool), + Str(Vec), + Debug(Vec), } -impl Drop for TracingProxy { - fn drop(&mut self) { - if !self.spans.is_empty() { - log::debug!( - target: "tracing", - "Dropping TracingProxy with {} un-exited spans, marking as not valid", self.spans.len() - ); - while let Some((_, mut sg)) = self.spans.pop() { - sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); - } - } + +#[derive(Encode, Decode)] +pub struct Fields (pub Vec<(Vec, FieldValue)>); + +impl Visit for Fields { + fn record_debug(&mut self, field: &Field, value: &dyn Debug) { + todo!{} + // self.0.push((field.name().as_bytes().into(), FieldValue::Debug(format!("{:?}", value).into()))); + } + fn record_i64(&mut self, field: &Field, value: i64) { + self.0.push((field.name().as_bytes().into(), FieldValue::I64(value))); + } + fn record_u64(&mut self, field: &Field, value: u64) { + self.0.push((field.name().as_bytes().into(), FieldValue::U64(value))); + } + fn record_bool(&mut self, field: &Field, value: bool) { + self.0.push((field.name().as_bytes().into(), FieldValue::Bool(value))); } + fn record_str(&mut self, field: &Field, value: &str) { + self.0.push((field.name().as_bytes().into(), FieldValue::Str(value.as_bytes().into()))); + } +} + +#[derive(Encode, Decode)] +pub struct TracingAttributes { + pub parent_id: Option, + pub fields: Fields } -impl TracingProxy { - pub fn new() -> TracingProxy { - TracingProxy { - next_id: 0, - spans: Vec::new(), +impl From<&Attributes<'_>> for TracingAttributes { + fn from(a: &Attributes) -> TracingAttributes { + let mut fields = Fields(Vec::new()); + a.record(&mut fields); + TracingAttributes { + parent_id: a.parent().map(|a| a.into_u64()), + fields } } } -impl TracingProxy { - /// Create and enter a `tracing` Span, returning the span id, - /// which should be passed to `exit_span(id)` to signal that the span should exit. - pub fn enter_span(&mut self, proxied_wasm_target: &str, proxied_wasm_name: &str) -> u64 { - // The identifiers `proxied_wasm_target` and `proxied_wasm_name` must match their associated const, - // WASM_TARGET_KEY and WASM_NAME_KEY. - let span = info_span!(WASM_TRACE_IDENTIFIER, is_valid_trace = true, proxied_wasm_target, proxied_wasm_name); - self.next_id += 1; - let sg = rent_span::SpanAndGuard::new( - Box::new(span), - |span| span.enter(), - ); - self.spans.push((self.next_id, sg)); - if self.spans.len() > MAX_SPANS_LEN { - // This is to prevent unbounded growth of Vec and could mean one of the following: - // 1. Too many nested spans, or MAX_SPANS_LEN is too low. - // 2. Not correctly exiting spans due to misconfiguration / misuse - log::warn!( - target: "tracing", - "TracingProxy MAX_SPANS_LEN exceeded, removing oldest span." - ); - let mut sg = self.spans.remove(0).1; - sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); + +#[derive(Encode, Decode)] +pub enum TracingLevel { + ERROR, + WARN, + INFO, + DEBUG, + TRACE +} + +impl From<&Level> for TracingLevel { + fn from(lvl: &Level) -> TracingLevel { + match *lvl { + Level::ERROR => TracingLevel::ERROR, + Level::WARN => TracingLevel::WARN, + Level::INFO => TracingLevel::INFO, + Level::DEBUG => TracingLevel::DEBUG, + Level::TRACE => TracingLevel::TRACE, } - self.next_id } +} - /// Exit a span by dropping it along with it's associated guard. - pub fn exit_span(&mut self, id: u64) { - if self.spans.last().map(|l| id > l.0).unwrap_or(true) { - log::warn!(target: "tracing", "Span id not found in TracingProxy: {}", id); - return; - } - let mut last_span = self.spans.pop().expect("Just checked that there is an element to pop; qed"); - while id < last_span.0 { - log::warn!( - target: "tracing", - "TracingProxy Span ids not equal! id parameter given: {}, last span: {}", - id, - last_span.0, - ); - last_span.1.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); - if let Some(s) = self.spans.pop() { - last_span = s; - } else { - log::warn!(target: "tracing", "Span id not found in TracingProxy {}", id); - return; - } +impl Into for TracingLevel { + fn into(self) -> Level { + match self { + TracingLevel::ERROR => Level::ERROR, + TracingLevel::WARN => Level::WARN, + TracingLevel::INFO => Level::INFO, + TracingLevel::DEBUG => Level::DEBUG, + TracingLevel::TRACE => Level::TRACE, } } } +#[derive(Encode, Decode)] +struct TracingMetadata { + name: Vec, + target: Vec, + level: TracingLevel, + file: Option>, + line: Option, + module_path: Option>, + fields: Vec>, + is_span: bool, +} -#[cfg(test)] -mod tests { - use super::*; - - fn create_spans(proxy: &mut TracingProxy, qty: usize) -> Vec { - let mut spans = Vec::new(); - for n in 0..qty { - spans.push(proxy.enter_span("target", &format!("{}", n))); +impl From<&Metadata<'_>> for TracingMetadata { + fn from(m: &Metadata) -> TracingMetadata { + TracingMetadata { + name: m.name().as_bytes().into(), + target: m.target().as_bytes().into(), + module_path: m.module_path().map(|m| m.as_bytes().into()), + file: m.file().map(|m| m.as_bytes().into()), + line: m.line().clone(), + level: m.level().into(), + fields: m.fields().iter().map(|f| f.name().as_bytes().into()).collect(), + is_span: m.is_span(), } - spans - } - - #[test] - fn max_spans_len_respected() { - let mut proxy = TracingProxy::new(); - let _spans = create_spans(&mut proxy, MAX_SPANS_LEN + 10); - assert_eq!(proxy.spans.len(), MAX_SPANS_LEN); - // ensure oldest spans removed - assert_eq!(proxy.spans[0].0, 11); - } - - #[test] - fn handles_span_exit_scenarios() { - let mut proxy = TracingProxy::new(); - let _spans = create_spans(&mut proxy, 10); - assert_eq!(proxy.spans.len(), 10); - // exit span normally - proxy.exit_span(10); - assert_eq!(proxy.spans.len(), 9); - // skip and exit outer span without exiting inner, id: 8 instead of 9 - proxy.exit_span(8); - // should have also removed the inner span that was lost - assert_eq!(proxy.spans.len(), 7); - // try to exit span not held - proxy.exit_span(9); - assert_eq!(proxy.spans.len(), 7); - // exit all spans - proxy.exit_span(1); - assert_eq!(proxy.spans.len(), 0); } } + + +trait WasmTracingInterface { + fn enabled(&self, metadata: &Metadata) -> bool; + fn new_span(&self, span: TracingAttributes) -> Id; + fn record(&self, span: &Id, values: &Record); + fn event(&self, event: &Event); + fn enter(&self, span: &Id); + fn exit(&self, span: &Id); +} \ No newline at end of file