Make some txpool logs a bit more compact (#1995)

* Improve logging for transaction pool.

* Change Debug in node-template runtime.

* Fix hexdisplay.

* Add some additional logging.

* Rebuild wasm

substrate/Cargo.lock

@@ -4271,6 +4271,7 @@ dependencies = [
  "serde 1.0.87 (registry+https://github.com/rust-lang/crates.io-index)",
  "serde_derive 1.0.87 (registry+https://github.com/rust-lang/crates.io-index)",
  "sr-primitives 0.1.0",
+ "substrate-primitives 0.1.0",
  "substrate-test-runtime 0.1.0",
 ]
 

substrate/core/basic-authorship/src/basic_authorship.rs

@@ -20,7 +20,7 @@
 //
 use std::{self, time, sync::Arc};
 
-use log::{info, debug, warn};
+use log::{info, debug, warn, trace};
 
 use client::{
 	self, error, Client as SubstrateClient, CallExecutor,
@@ -227,6 +227,7 @@ impl<Block, C, A> Proposer<Block, C, A>	where
 						break;
 					}
 
+					trace!("[{:?}] Pushing to the block.", pending.hash);
 					match block_builder.push_extrinsic(pending.data.clone()) {
 						Ok(()) => {
 							debug!("[{:?}] Pushed to the block.", pending.hash);

substrate/core/sr-primitives/src/lib.rs

@@ -661,9 +661,15 @@ macro_rules! impl_outer_log {
 /// Simple blob to hold an extrinsic without committing to its format and ensure it is serialized
 /// correctly.
 #[derive(PartialEq, Eq, Clone, Default, Encode, Decode)]
-#[cfg_attr(feature = "std", derive(Debug))]
 pub struct OpaqueExtrinsic(pub Vec<u8>);
 
+#[cfg(feature = "std")]
+impl std::fmt::Debug for OpaqueExtrinsic {
+	fn fmt(&self, fmt: &mut std::fmt::Formatter) -> std::fmt::Result {
+		write!(fmt, "{}", substrate_primitives::hexdisplay::HexDisplay::from(&self.0))
+	}
+}
+
 #[cfg(feature = "std")]
 impl ::serde::Serialize for OpaqueExtrinsic {
 	fn serialize<S>(&self, seq: S) -> Result<S::Ok, S::Error> where S: ::serde::Serializer {

substrate/core/transaction-pool/graph/Cargo.toml

@@ -11,6 +11,7 @@ log = "0.4"
 parking_lot = "0.7.1"
 serde = "1.0"
 serde_derive = "1.0"
+substrate-primitives = { path = "../../primitives" }
 sr-primitives = { path = "../../sr-primitives" }
 
 [dev-dependencies]

substrate/core/transaction-pool/graph/src/base_pool.rs

@@ -19,13 +19,15 @@
 //! For a more full-featured pool, have a look at the `pool` module.
 
 use std::{
+	fmt,
 	hash,
 	sync::Arc,
 };
 
-use serde::Serialize;
 use error_chain::bail;
 use log::{trace, debug, warn};
+use serde::Serialize;
+use substrate_primitives::hexdisplay::HexDisplay;
 use sr_primitives::traits::Member;
 use sr_primitives::transaction_validity::{
 	TransactionTag as Tag,
@@ -82,7 +84,7 @@ pub struct PruneStatus<Hash, Ex> {
 
 /// Immutable transaction
 #[cfg_attr(test, derive(Clone))]
-#[derive(Debug, PartialEq, Eq)]
+#[derive(PartialEq, Eq)]
 pub struct Transaction<Hash, Extrinsic> {
 	/// Raw extrinsic representing that transaction.
 	pub data: Extrinsic,
@@ -100,6 +102,38 @@ pub struct Transaction<Hash, Extrinsic> {
 	pub provides: Vec<Tag>,
 }
 
+impl<Hash, Extrinsic> fmt::Debug for Transaction<Hash, Extrinsic> where
+	Hash: fmt::Debug,
+	Extrinsic: fmt::Debug,
+{
+	fn fmt(&self, fmt: &mut fmt::Formatter) -> fmt::Result {
+		fn print_tags(fmt: &mut fmt::Formatter, tags: &[Tag]) -> fmt::Result {
+			let mut it = tags.iter();
+			if let Some(t) = it.next() {
+				write!(fmt, "{}", HexDisplay::from(t))?;
+			}
+			for t in it {
+				write!(fmt, ",{}", HexDisplay::from(t))?;
+			}
+			Ok(())
+		}
+
+		write!(fmt, "Transaction {{ ")?;
+		write!(fmt, "hash: {:?}, ", &self.hash)?;
+		write!(fmt, "priority: {:?}, ", &self.priority)?;
+		write!(fmt, "valid_till: {:?}, ", &self.valid_till)?;
+		write!(fmt, "bytes: {:?}, ", &self.bytes)?;
+		write!(fmt, "requires: [")?;
+		print_tags(fmt, &self.requires)?;
+		write!(fmt, "], provides: [")?;
+		print_tags(fmt, &self.provides)?;
+		write!(fmt, "], ")?;
+		write!(fmt, "data: {:?}", &self.data)?;
+		write!(fmt, "}}")?;
+		Ok(())
+	}
+}
+
 /// Transaction pool.
 ///
 /// Builds a dependency graph for all transactions in the pool and returns
@@ -360,6 +394,7 @@ impl<Hash: hash::Hash + Member + Serialize, Ex: ::std::fmt::Debug> BasePool<Hash
 }
 
 /// Pool status
+#[derive(Debug)]
 pub struct Status {
 	/// Number of transactions in the ready queue.
 	pub ready: usize,
@@ -837,4 +872,20 @@ mod tests {
 		assert_eq!(pool.ready().count(), 3);
 	}
 
+	#[test]
+	fn transaction_debug() {
+		assert_eq!(
+			format!("{:?}", Transaction {
+				data: vec![4u8],
+				bytes: 1,
+				hash: 4,
+				priority: 1_000u64,
+				valid_till: 64u64,
+				requires: vec![vec![3], vec![2]],
+				provides: vec![vec![4]],
+			}),
+			r#"Transaction { hash: 4, priority: 1000, valid_till: 64, bytes: 1, requires: [03,02], provides: [04], data: [4]}"#.to_owned()
+		);
+	}
+
 }

substrate/core/transaction-pool/graph/src/future.rs

@@ -16,11 +16,13 @@
 
 use std::{
 	collections::{HashMap, HashSet},
+	fmt,
 	hash,
 	sync::Arc,
 	time,
 };
 
+use substrate_primitives::hexdisplay::HexDisplay;
 use sr_primitives::transaction_validity::{
 	TransactionTag as Tag,
 };
@@ -28,7 +30,6 @@ use sr_primitives::transaction_validity::{
 use crate::base_pool::Transaction;
 
 /// Transaction with partially satisfied dependencies.
-#[derive(Debug)]
 pub struct WaitingTransaction<Hash, Ex> {
 	/// Transaction details.
 	pub transaction: Arc<Transaction<Hash, Ex>>,
@@ -38,6 +39,23 @@ pub struct WaitingTransaction<Hash, Ex> {
 	pub imported_at: time::Instant,
 }
 
+impl<Hash: fmt::Debug, Ex: fmt::Debug> fmt::Debug for WaitingTransaction<Hash, Ex> {
+	fn fmt(&self, fmt: &mut fmt::Formatter) -> fmt::Result {
+		write!(fmt, "WaitingTransaction {{ ")?;
+		write!(fmt, "imported_at: {:?}, ", self.imported_at)?;
+		write!(fmt, "transaction: {:?}, ", self.transaction)?;
+		write!(fmt, "missing_tags: {{")?;
+		let mut it = self.missing_tags.iter().map(|tag| HexDisplay::from(tag));
+		if let Some(tag) = it.next() {
+			write!(fmt, "{}", tag)?;
+		}
+		for tag in it {
+			write!(fmt, ", {}", tag)?;
+		}
+		write!(fmt, " }}}}")
+	}
+}
+
 impl<Hash, Ex> Clone for WaitingTransaction<Hash, Ex> {
 	fn clone(&self) -> Self {
 		WaitingTransaction {

substrate/core/transaction-pool/graph/src/pool.rs

@@ -176,6 +176,8 @@ impl<B: ChainApi> Pool<B> {
 		let ready_limit = &self.options.ready;
 		let future_limit = &self.options.future;
 
+		debug!(target: "txpool", "Pool Status: {:?}", status);
+
 		if ready_limit.is_exceeded(status.ready, status.ready_bytes)
 			|| future_limit.is_exceeded(status.future, status.future_bytes) {
 			// clean up the pool

substrate/node-template/runtime/src/lib.rs

@@ -67,8 +67,14 @@ pub mod opaque {
 
 	/// Opaque, encoded, unchecked extrinsic.
 	#[derive(PartialEq, Eq, Clone, Default, Encode, Decode)]
-	#[cfg_attr(feature = "std", derive(Serialize, Deserialize, Debug))]
+	#[cfg_attr(feature = "std", derive(Serialize, Deserialize))]
 	pub struct UncheckedExtrinsic(#[cfg_attr(feature = "std", serde(with="bytes"))] pub Vec<u8>);
+	#[cfg(feature = "std")]
+	impl std::fmt::Debug for UncheckedExtrinsic {
+		fn fmt(&self, fmt: &mut std::fmt::Formatter) -> std::fmt::Result {
+			write!(fmt, "{}", primitives::hexdisplay::HexDisplay::from(&self.0))
+		}
+	}
 	impl traits::Extrinsic for UncheckedExtrinsic {
 		fn is_signed(&self) -> Option<bool> {
 			None