Skip to content

Commit

Permalink
make tracing codecable
Browse files Browse the repository at this point in the history
  • Loading branch information
gnunicorn committed Jul 23, 2020
1 parent 0b7b16e commit 70492f5
Show file tree
Hide file tree
Showing 3 changed files with 167 additions and 127 deletions.
2 changes: 2 additions & 0 deletions Cargo.lock

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

20 changes: 18 additions & 2 deletions primitives/tracing/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -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"
]
272 changes: 147 additions & 125 deletions primitives/tracing/src/proxy.rs
Original file line number Diff line number Diff line change
Expand Up @@ -14,152 +14,174 @@
// You should have received a copy of the GNU General Public License
// along with Substrate. If not, see <http://www.gnu.org/licenses/>.

#![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<tracing::Span>,
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<u8>),
Debug(Vec<u8>),
}

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<u8>, 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<u64>,
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<Level> 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<u8>,
target: Vec<u8>,
level: TracingLevel,
file: Option<Vec<u8>>,
line: Option<u32>,
module_path: Option<Vec<u8>>,
fields: Vec<Vec<u8>>,
is_span: bool,
}

#[cfg(test)]
mod tests {
use super::*;

fn create_spans(proxy: &mut TracingProxy, qty: usize) -> Vec<u64> {
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);
}

0 comments on commit 70492f5

Please sign in to comment.