RPC to trace execution of specified block (#7780)

* Add filter reload handle

* add RPC, move logging module from cli to tracing

* remove dup fn

* working example

* Update client/rpc-api/src/system/mod.rs

Co-authored-by: Pierre Krieger <pierre.krieger1708@gmail.com>

* Prefer "set" to "reload"

* Re-enable the commented out features of the logger

* Remove duplicate code

* cleanup

* unneeded lvar

* Bump to latest patch release

* Add new CLI option to disable log filter reloading,

Move profiling CLI options to SharedParams

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Applied suggestions from reviews

* Fix calls to init_logger()

* Handle errors when parsing logging directives

* Deny `system_setLogFilter` RPC by default

* One more time

* Don't ignore parse errors for log directives set via CLI or RPC

* Improve docs

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Update client/cli/src/config.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* fix merge errors

* include default directives with system_setLogFilter RPC,

implement system_rawSetLogFilter RPC to exclude defaults

* docs etc...

* update test

* refactor: rename fn

* Add a test for system_set_log_filter – NOTE: the code should likely change to return an error when bad directives are passed

* Update client/cli/src/lib.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Address review grumbles

* Add doc note on panicking behaviour

* print all invalid directives before panic

* change RPCs to: addLogFilter and resetLogFilter

* make CLI log directives default

* add comments

* restore previous behaviour to panic when hard-coded directives are invalid

* change/refactor directive parsing

* fix line width

* add test for log filter reloading

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* finish up suggestions from code review

* improve test

* change expect message

* change fn name

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* add docs, remove unused fn

* propagate Err on invalid log directive

* Update tracing-subscriber version

* Improve docs for `disable_log_reloading` CLI param

* WIP implementation: RPC and trace capturing

* WIP

* fix incorrect number of digest items

* return errors

* add From impl for Values, rename structs

* fixes

* implement option to choose targets for traces

* rename fn

* fix EnvFilter and add root span

* fix root span

* add docs, remove unnecessary traits

* fix regression on parent_id introduced in a9c73113a8

* fix line width

* remove unused

* include block hash, parent hash & targets in response

* move types from sp-tracing into sp-rpc

move block and parent hash into root of BlockTrace

* switch from log::trace to tracing::trace in state-machine

* use unsigned integer type to represent Ext::id in traces

* ensure id is unique by implementing Subscriber

tracing_subscriber::FmtSubscriber does not guarantee
unique ids

* indentation

* fix typo

* update types

* add sp_io::storage events

* Change response format

- update types
- record distinct timestamps
- sort spans by first entered

* convert to HexDisplay, refactor

* Sort out fallout from merge

* Update client/rpc-api/src/state/mod.rs

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Exit early unless the node runs with --rpc-methods=Unsafe

* Better error handling

* Use wasm-timer

* revert trace alteration in `state-machine` and remove events in `sp_io::storage`

Resolve in follow-up PR

* Review feedback: less collects

* Without Arcs

* Fix span exit

* typo

* cleanup

* Add a few debug messages to tracing module

* Structure traces state-machine/ext; Dispatchable extrinsics spans not working

* Correctly encode Option storage values

* Remove test field for Put and Get

* Try out some changes to dispatch macro

* Add various log messages in dispatch

* Add span dispatch span to new proc macro

* Remove debug messages in dispatch

* Trivial clean up

* Structure remaining state-machine traces (ChangesRoot*)

* Removed unnesecary tracing targets

* Remove log

* New cargo.lock post merge

* Add logging for wasm_overrides

* remove temp logs

* remove temp logs

* remove unused dep

* remove temp logs

* add logging to wasm_overrides

* add logging to state_tracing

* add logging for spans to substrate (includes timings)

* Skip serializing some event fields; Remove most storage traces

* Bring back all ext.rs traces

* Do not skip bool values in events

* Skip serializing span values

* Serialize span values; remove some trace events in ext

* Remove more trace events

* Delete commented out traces

* Remove all unused traces

* Add event filtering

* Fix typo

* wip - change response types to be more efficient

missing import

type

* Serialize struct fields as camelCase

* Add back in event filtering

* Remove name field from event

* Sort spans by time entered

* Sort spans in ASCending order

* Add storage keys target param to rpc

* Limit payload size; improve hash fields; include storage keys

- cleanup event_key_filter
- better block hash representation
- limit payload size
- cleanup based on andrews comments

* Error when serialized payload is to big

* Import MAX_PAYLOAD from rpc-servers

* Clean up ext.rs

* Misc. cleaning and comments

* Strict ordering span Id; no span sort; adjust for rpc base payload

* Add RPC docs to rpc-api/src/state/mod

* Make params bullet points

* Update primitives/rpc/src/tracing.rs

* Put all tracing logic within trace

* Remove attr.record in new_span

* Add back value record in new_span

* restore result collection in ext

* Revert "Add back value record in new_span"

This reverts commit baf1a735f23e5eef1bf6264adfabb788910fa661.

* 🤦

* more 🤦

* Update docs; Try fix line width issues

* Improve docs

* Improve docs

* Remove default key filters + add key recs to docs

* Try restore old traces

* Add back doc comment

* Clean up newlines in ext.rs

* More new line remova;
l

* Use FxHashMap

* Try use EnvFilter directives for event filtering

* Remove directive, filter events by fields

* Use trace metadata correctly

* Try EnvFilter directive with all default targets

* Revert "Try EnvFilter directive with all default targets"

This reverts commit 4cc6ebc721d207c3b846444174f89d45038525ac.

* Clean up clippy warning

* Incorporate Niklas feedback

* Update trace/log macro calls to have better syntx

* Use Ordering::Relaxed

* Improve patch and filter doc comment

* Clean up `BlockSubscriber::new`

* Try optimize `BlockSubscriber::enabled`

* Apply suggestions from code review

Co-authored-by: David <dvdplm@gmail.com>

* Apply suggestions from code review

Co-authored-by: David <dvdplm@gmail.com>

* Use contains_key

* use heuristic for payload size

* Add error tupe for client::tracing::block

* Minor tweaks

* Make a note about `--features with-tracing`

* Add CURL example to RPC docs

* Link to substrate-archibe wasm

* Trivial doc clean up based on David feedback

* Explicit result type name

* Respect line length

* Use the error

* Don't print timings when spans close

* Fix failing sc-rpc-api

* Update  sp-tracing inner-line doc

* Update client/tracing/src/block/mod.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Update client/service/src/client/call_executor.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Update client/service/src/client/call_executor.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Update client/tracing/src/block/mod.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Update client/tracing/src/block/mod.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Address some review grumbles

* Update primitives/state-machine/src/ext.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Use result_encoded structure fields in ext.rs

* Use value key for ext put

* Add notes about tracing key names matter

Co-authored-by: Matt <mattrutherford@users.noreply.github.com>
Co-authored-by: David <dvdplm@gmail.com>
Co-authored-by: Pierre Krieger <pierre.krieger1708@gmail.com>
Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>
Co-authored-by: emostov <32168567+emostov@users.noreply.github.com>

substrate/client/tracing/src/lib.rs

@@ -29,6 +29,7 @@
 #![warn(missing_docs)]
 
 pub mod logging;
+pub mod block;
 
 use rustc_hash::FxHashMap;
 use std::fmt;
@@ -86,7 +87,7 @@ pub trait TraceHandler: Send + Sync {
 #[derive(Debug)]
 pub struct TraceEvent {
 	/// Name of the event.
-	pub name: &'static str,
+	pub name: String,
 	/// Target of the event.
 	pub target: String,
 	/// Level of the event.
@@ -123,13 +124,13 @@ pub struct SpanDatum {
 /// Holds associated values for a tracing span
 #[derive(Default, Clone, Debug)]
 pub struct Values {
-	/// HashMap of `bool` values
+	/// FxHashMap of `bool` values
 	pub bool_values: FxHashMap<String, bool>,
-	/// HashMap of `i64` values
+	/// FxHashMap of `i64` values
 	pub i64_values: FxHashMap<String, i64>,
-	/// HashMap of `u64` values
+	/// FxHashMap of `u64` values
 	pub u64_values: FxHashMap<String, u64>,
-	/// HashMap of `String` values
+	/// FxHashMap of `String` values
 	pub string_values: FxHashMap<String, String>,
 }
 
@@ -265,7 +266,7 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
 			parent_id: attrs.parent().cloned().or_else(|| self.current_span.id()),
 			name: attrs.metadata().name().to_owned(),
 			target: attrs.metadata().target().to_owned(),
-			level: attrs.metadata().level().clone(),
+			level: *attrs.metadata().level(),
 			line: attrs.metadata().line().unwrap_or(0),
 			start_time: Instant::now(),
 			overall_time: ZERO_DURATION,
@@ -285,9 +286,9 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
 		let mut values = Values::default();
 		event.record(&mut values);
 		let trace_event = TraceEvent {
-			name: event.metadata().name(),
+			name: event.metadata().name().to_owned(),
 			target: event.metadata().target().to_owned(),
-			level: event.metadata().level().clone(),
+			level: *event.metadata().level(),
 			values,
 			parent_id: event.parent().cloned().or_else(|| self.current_span.id()),
 		};
@@ -304,7 +305,6 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
 	}
 
 	fn on_exit(&self, span: &Id, _ctx: Context<S>) {
-		self.current_span.exit();
 		let end_time = Instant::now();
 		let span_datum = {
 			let mut span_data = self.span_data.lock();
@@ -312,6 +312,8 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
 		};
 
 		if let Some(mut span_datum) = span_datum {
+			// If `span_datum` is `None` we don't exit (we'd be exiting the parent span)
+			self.current_span.exit();
 			span_datum.overall_time += end_time - span_datum.start_time;
 			if span_datum.name == WASM_TRACE_IDENTIFIER {
 				span_datum.values.bool_values.insert("wasm".to_owned(), true);
@@ -330,9 +332,7 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
 		};
 	}
 
-	fn on_close(&self, span: Id, ctx: Context<S>) {
-		self.on_exit(&span, ctx)
-	}
+	fn on_close(&self, _span: Id, _ctx: Context<S>) {}
 }
 
 /// TraceHandler for sending span data to the logger
@@ -385,6 +385,32 @@ impl TraceHandler for LogTraceHandler {
 	}
 }
 
+impl From<TraceEvent> for sp_rpc::tracing::Event {
+	fn from(trace_event: TraceEvent) -> Self {
+		let data = sp_rpc::tracing::Data {
+			string_values: trace_event.values.string_values
+		};
+		sp_rpc::tracing::Event {
+			target: trace_event.target,
+			data,
+			parent_id: trace_event.parent_id.map(|id| id.into_u64())
+		}
+	}
+}
+
+impl From<SpanDatum> for sp_rpc::tracing::Span {
+	fn from(span_datum: SpanDatum) -> Self {
+		let wasm = span_datum.values.bool_values.get("wasm").is_some();
+		sp_rpc::tracing::Span {
+			id: span_datum.id.into_u64(),
+			parent_id: span_datum.parent_id.map(|id| id.into_u64()),
+			name: span_datum.name,
+			target: span_datum.target,
+			wasm,
+		}
+	}
+}
+
 #[cfg(test)]
 mod tests {
 	use super::*;
@@ -555,7 +581,7 @@ mod tests {
 						break;
 					}
 				}
-				// gard2 and span2 dropped / exited
+				// guard2 and span2 dropped / exited
 			});
 
 			// wait for Event to be dispatched and stored