referrerpolicy=no-referrer-when-downgrade

sc_tracing/block/
mod.rs

1// Copyright (C) Parity Technologies (UK) Ltd.
2// This file is part of Substrate.
3// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
4
5// Substrate is free software: you can redistribute it and/or modify
6// it under the terms of the GNU General Public License as published by
7// the Free Software Foundation, either version 3 of the License, or
8// (at your option) any later version.
9
10// Substrate is distributed in the hope that it will be useful,
11// but WITHOUT ANY WARRANTY; without even the implied warranty of
12// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
13// GNU General Public License for more details.
14
15// You should have received a copy of the GNU General Public License
16// along with Substrate. If not, see <https://www.gnu.org/licenses/>.
17
18//! Utilities for tracing block execution
19
20use std::{
21	collections::HashMap,
22	sync::{
23		atomic::{AtomicU64, Ordering},
24		Arc,
25	},
26	time::Instant,
27};
28
29use codec::Encode;
30use parking_lot::Mutex;
31use tracing::{
32	dispatcher,
33	span::{Attributes, Id, Record},
34	Dispatch, Level, Subscriber,
35};
36
37use crate::{SpanDatum, TraceEvent, Values};
38use sc_client_api::BlockBackend;
39use sp_api::{Core, Metadata, ProvideRuntimeApi};
40use sp_blockchain::HeaderBackend;
41use sp_core::hexdisplay::HexDisplay;
42use sp_rpc::tracing::{BlockTrace, Span, TraceBlockResponse};
43use sp_runtime::{
44	generic::BlockId,
45	traits::{Block as BlockT, Header},
46};
47use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
48
49// Default to only pallet, frame support and state related traces
50const DEFAULT_TARGETS: &str = "pallet,frame,state";
51const TRACE_TARGET: &str = "block_trace";
52// The name of a field required for all events.
53const REQUIRED_EVENT_FIELD: &str = "method";
54
55/// Tracing Block Result type alias
56pub type TraceBlockResult<T> = Result<T, Error>;
57
58/// Tracing Block error
59#[derive(Debug, thiserror::Error)]
60#[allow(missing_docs)]
61#[non_exhaustive]
62pub enum Error {
63	#[error("Invalid block Id: {0}")]
64	InvalidBlockId(#[from] sp_blockchain::Error),
65	#[error("Missing block component: {0}")]
66	MissingBlockComponent(String),
67	#[error("Dispatch error: {0}")]
68	Dispatch(String),
69}
70
71struct BlockSubscriber {
72	targets: Vec<(String, Level)>,
73	next_id: AtomicU64,
74	spans: Mutex<HashMap<Id, SpanDatum>>,
75	events: Mutex<Vec<TraceEvent>>,
76}
77
78impl BlockSubscriber {
79	fn new(targets: &str) -> Self {
80		let next_id = AtomicU64::new(1);
81		let mut targets: Vec<_> = targets.split(',').map(crate::parse_target).collect();
82		// Ensure that WASM traces are always enabled
83		// Filtering happens when decoding the actual target / level
84		targets.push((WASM_TRACE_IDENTIFIER.to_owned(), Level::TRACE));
85		BlockSubscriber {
86			targets,
87			next_id,
88			spans: Mutex::new(HashMap::new()),
89			events: Mutex::new(Vec::new()),
90		}
91	}
92}
93
94impl Subscriber for BlockSubscriber {
95	fn enabled(&self, metadata: &tracing::Metadata<'_>) -> bool {
96		if !metadata.is_span() && metadata.fields().field(REQUIRED_EVENT_FIELD).is_none() {
97			return false
98		}
99		for (target, level) in &self.targets {
100			if metadata.level() <= level && metadata.target().starts_with(target) {
101				return true
102			}
103		}
104		false
105	}
106
107	fn new_span(&self, attrs: &Attributes<'_>) -> Id {
108		let id = Id::from_u64(self.next_id.fetch_add(1, Ordering::Relaxed));
109		let mut values = Values::default();
110		attrs.record(&mut values);
111		let parent_id = attrs.parent().cloned();
112		let span = SpanDatum {
113			id: id.clone(),
114			parent_id,
115			name: attrs.metadata().name().to_owned(),
116			target: attrs.metadata().target().to_owned(),
117			level: *attrs.metadata().level(),
118			line: attrs.metadata().line().unwrap_or(0),
119			start_time: Instant::now(),
120			values,
121			overall_time: Default::default(),
122		};
123
124		self.spans.lock().insert(id.clone(), span);
125		id
126	}
127
128	fn record(&self, span: &Id, values: &Record<'_>) {
129		let mut span_data = self.spans.lock();
130		if let Some(s) = span_data.get_mut(span) {
131			values.record(&mut s.values);
132		}
133	}
134
135	fn record_follows_from(&self, _span: &Id, _follows: &Id) {
136		// Not currently used
137		unimplemented!("record_follows_from is not implemented");
138	}
139
140	fn event(&self, event: &tracing::Event<'_>) {
141		let mut values = crate::Values::default();
142		event.record(&mut values);
143		let parent_id = event.parent().cloned();
144		let trace_event = TraceEvent {
145			name: event.metadata().name().to_owned(),
146			target: event.metadata().target().to_owned(),
147			level: *event.metadata().level(),
148			values,
149			parent_id,
150		};
151		self.events.lock().push(trace_event);
152	}
153
154	fn enter(&self, _id: &Id) {}
155
156	fn exit(&self, _span: &Id) {}
157}
158
159/// Holds a reference to the client in order to execute the given block.
160/// Records spans & events for the supplied targets (eg. "pallet,frame,state") and
161/// only records events with the specified hex encoded storage key prefixes.
162/// Note: if `targets` or `storage_keys` is an empty string then nothing is
163/// filtered out.
164pub struct BlockExecutor<Block: BlockT, Client> {
165	client: Arc<Client>,
166	block: Block::Hash,
167	targets: Option<String>,
168	storage_keys: Option<String>,
169	methods: Option<String>,
170}
171
172impl<Block, Client> BlockExecutor<Block, Client>
173where
174	Block: BlockT + 'static,
175	Client: HeaderBackend<Block>
176		+ BlockBackend<Block>
177		+ ProvideRuntimeApi<Block>
178		+ Send
179		+ Sync
180		+ 'static,
181	Client::Api: Metadata<Block>,
182{
183	/// Create a new `BlockExecutor`
184	pub fn new(
185		client: Arc<Client>,
186		block: Block::Hash,
187		targets: Option<String>,
188		storage_keys: Option<String>,
189		methods: Option<String>,
190	) -> Self {
191		Self { client, block, targets, storage_keys, methods }
192	}
193
194	/// Execute block, record all spans and events belonging to `Self::targets`
195	/// and filter out events which do not have keys starting with one of the
196	/// prefixes in `Self::storage_keys`.
197	pub fn trace_block(&self) -> TraceBlockResult<TraceBlockResponse> {
198		tracing::debug!(target: "state_tracing", "Tracing block: {}", self.block);
199		// Prepare the block
200		let mut header = self
201			.client
202			.header(self.block)
203			.map_err(Error::InvalidBlockId)?
204			.ok_or_else(|| Error::MissingBlockComponent("Header not found".to_string()))?;
205		let extrinsics = self
206			.client
207			.block_body(self.block)
208			.map_err(Error::InvalidBlockId)?
209			.ok_or_else(|| Error::MissingBlockComponent("Extrinsics not found".to_string()))?;
210		tracing::debug!(target: "state_tracing", "Found {} extrinsics", extrinsics.len());
211		let parent_hash = *header.parent_hash();
212		// Remove all `Seal`s as they are added by the consensus engines after building the block.
213		// On import they are normally removed by the consensus engine.
214		header.digest_mut().logs.retain(|d| d.as_seal().is_none());
215		let block = Block::new(header, extrinsics);
216
217		let targets = if let Some(t) = &self.targets { t } else { DEFAULT_TARGETS };
218		let block_subscriber = BlockSubscriber::new(targets);
219		let dispatch = Dispatch::new(block_subscriber);
220
221		{
222			let dispatcher_span = tracing::debug_span!(
223				target: "state_tracing",
224				"execute_block",
225				extrinsics_len = block.extrinsics().len(),
226			);
227			let _guard = dispatcher_span.enter();
228			if let Err(e) = dispatcher::with_default(&dispatch, || {
229				let span = tracing::info_span!(target: TRACE_TARGET, "trace_block");
230				let _enter = span.enter();
231				self.client.runtime_api().execute_block(parent_hash, block)
232			}) {
233				return Err(Error::Dispatch(format!(
234					"Failed to collect traces and execute block: {}",
235					e
236				)))
237			}
238		}
239
240		let block_subscriber = dispatch.downcast_ref::<BlockSubscriber>().ok_or_else(|| {
241			Error::Dispatch(
242				"Cannot downcast Dispatch to BlockSubscriber after tracing block".to_string(),
243			)
244		})?;
245		let spans: Vec<_> = block_subscriber
246			.spans
247			.lock()
248			.drain()
249			// Patch wasm identifiers
250			.filter_map(|(_, s)| patch_and_filter(s, targets))
251			.collect();
252		let events: Vec<_> = block_subscriber
253			.events
254			.lock()
255			.drain(..)
256			.filter(|e| {
257				self.storage_keys
258					.as_ref()
259					.map(|keys| event_values_filter(e, "key", keys))
260					.unwrap_or(false)
261			})
262			.filter(|e| {
263				self.methods
264					.as_ref()
265					.map(|methods| event_values_filter(e, "method", methods))
266					.unwrap_or(false)
267			})
268			.map(|s| s.into())
269			.collect();
270		tracing::debug!(target: "state_tracing", "Captured {} spans and {} events", spans.len(), events.len());
271
272		Ok(TraceBlockResponse::BlockTrace(BlockTrace {
273			block_hash: block_id_as_string(BlockId::<Block>::Hash(self.block)),
274			parent_hash: block_id_as_string(BlockId::<Block>::Hash(parent_hash)),
275			tracing_targets: targets.to_string(),
276			storage_keys: self.storage_keys.clone().unwrap_or_default(),
277			methods: self.methods.clone().unwrap_or_default(),
278			spans,
279			events,
280		}))
281	}
282}
283
284fn event_values_filter(event: &TraceEvent, filter_kind: &str, values: &str) -> bool {
285	event
286		.values
287		.string_values
288		.get(filter_kind)
289		.map(|value| check_target(values, value, &event.level))
290		.unwrap_or(false)
291}
292
293/// Filter out spans that do not match our targets and if the span is from WASM update its `name`
294/// and `target` fields to the WASM values for those fields.
295// The `tracing` crate requires trace metadata to be static. This does not work for wasm code in
296// substrate, as it is regularly updated with new code from on-chain events. The workaround for this
297// is for substrate's WASM tracing wrappers to put the `name` and `target` data in the `values` map
298// (normally they would be in the static metadata assembled at compile time). Here, if a special
299// WASM `name` or `target` key is found in the `values` we remove it and put the key value pair in
300// the span's metadata, making it consistent with spans that come from native code.
301fn patch_and_filter(mut span: SpanDatum, targets: &str) -> Option<Span> {
302	if span.name == WASM_TRACE_IDENTIFIER {
303		span.values.bool_values.insert("wasm".to_owned(), true);
304		if let Some(n) = span.values.string_values.remove(WASM_NAME_KEY) {
305			span.name = n;
306		}
307		if let Some(t) = span.values.string_values.remove(WASM_TARGET_KEY) {
308			span.target = t;
309		}
310		if !check_target(targets, &span.target, &span.level) {
311			return None
312		}
313	}
314	Some(span.into())
315}
316
317/// Check if a `target` matches any `targets` by prefix
318fn check_target(targets: &str, target: &str, level: &Level) -> bool {
319	for (t, l) in targets.split(',').map(crate::parse_target) {
320		if target.starts_with(t.as_str()) && level <= &l {
321			return true
322		}
323	}
324	false
325}
326
327fn block_id_as_string<T: BlockT>(block_id: BlockId<T>) -> String {
328	match block_id {
329		BlockId::Hash(h) => HexDisplay::from(&h.encode()).to_string(),
330		BlockId::Number(n) => HexDisplay::from(&n.encode()).to_string(),
331	}
332}