Add tracing to DKG (#486)

Co-authored-by: drewstone <drewstone329@gmail.com>

Cargo.toml

@@ -10,4 +10,5 @@ members = [
 	'dkg-primitives',
 	'dkg-runtime-primitives',
 	'dkg-gadget',
+	'dkg-logging'
 ]

README.md

@@ -253,6 +253,13 @@ cargo test
 
 **Note:** You may also run individual E2E tests. Please review test script commands in `dkg-test-suite/package.json` for verbose list of test cases. See below examples.
 
+### E2E tests w/tracing
+`tracing` is a feature that can be useful for analyzing causality inside the DKG. To enable tracing, the `dkg-standalone-node` must be compiled with the feature `tracing` enabled.
+```
+1. Compile dkg-standalone-node with tracing: `cargo build --package dkg-standalone-node --release --features=tracing,integration-tests`
+2. Run the nodes, setting the env-vars to trace: `RUST_LOG=dkg=trace ./target/release/dkg-standalone-node --tmp --alice`
+```
+
 ### Anchor Proposal tests:
 
 **From terminal 1:**

dkg-gadget/Cargo.toml

@@ -7,11 +7,11 @@ license = "GPL-3.0-or-later WITH Classpath-exception-2.0"
 
 [features]
 outbound-inspection = []
+tracing = []
 
 [dependencies]
 fnv = "1.0.6"
 futures = "0.3"
-log = { version = "0.4" }
 parking_lot = "0.11"
 thiserror = "1.0"
 wasm-timer = "0.2.5"
@@ -55,12 +55,14 @@ atomic = "0.5.1"
 async-trait = "0.1.53"
 auto_impl = "1.0.0"
 itertools = "0.10.3"
+tracing = "0.1.37"
 
 webb-proposals = { version = "0.5.4", default-features = false, features = ["scale", "evm", "substrate"] }
 
 # Local dependencies
 dkg-runtime-primitives = { path = "../dkg-runtime-primitives" }
 dkg-primitives = { path = "../dkg-primitives", default-features = false }
+dkg-logging = { path = "../dkg-logging" }
 
 [dev-dependencies]
 sc-network-test = { git = "https://github.com/paritytech/substrate", branch = "polkadot-v0.9.36", default-features = false }

dkg-gadget/src/async_protocols/blockchain_interface.rs

@@ -148,7 +148,7 @@ where
 	) -> Result<(), DKGError> {
 		// Call worker.rs: handle_finished_round -> Proposal
 		// aggregate Proposal into Vec<Proposal>
-		log::info!(target: "dkg", "PROCESS VOTE RESULT : session_id {:?}, signature : {:?}", session_id, signature);
+		dkg_logging::info!(target: "dkg", "PROCESS VOTE RESULT : session_id {:?}, signature : {:?}", session_id, signature);
 		let payload_key = unsigned_proposal.key;
 		let signature = convert_signature(&signature).ok_or_else(|| DKGError::CriticalError {
 			reason: "Unable to serialize signature".to_string(),
@@ -169,7 +169,7 @@ where
 			proposals_for_this_batch.push(proposal);
 
 			if proposals_for_this_batch.len() == batch_key.len {
-				log::info!(target: "dkg", "All proposals have resolved for batch {:?}", batch_key);
+				dkg_logging::info!(target: "dkg", "All proposals have resolved for batch {:?}", batch_key);
 				let proposals = lock.remove(&batch_key).unwrap(); // safe unwrap since lock is held
 				std::mem::drop(lock);
 				save_signed_proposals_in_storage::<B, C, BE>(
@@ -180,7 +180,7 @@ where
 					proposals,
 				);
 			} else {
-				log::info!(target: "dkg", "{}/{} proposals have resolved for batch {:?}", proposals_for_this_batch.len(), batch_key.len, batch_key);
+				dkg_logging::info!(target: "dkg", "{}/{} proposals have resolved for batch {:?}", proposals_for_this_batch.len(), batch_key.len, batch_key);
 			}
 		}
 

dkg-gadget/src/async_protocols/incoming.rs

@@ -83,17 +83,18 @@ impl TransformIncoming for Arc<SignedDKGMessage<Public>> {
 							.verify_signature_against_authorities(self)
 							.map(|body| Some(Msg { sender, receiver: None, body }))
 					} else {
-						log::warn!(target: "dkg", "Will skip passing message to state machine since not for this round, msg round {:?} this session {:?}", self.msg.session_id, this_session_id);
+						dkg_logging::warn!(target: "dkg", "Will skip passing message to state machine since not for this round, msg round {:?} this session {:?}", self.msg.session_id, this_session_id);
 						Ok(None)
 					}
 				} else {
-					log::trace!(target: "dkg", "Will skip passing message to state machine since sender is self");
+					dkg_logging::trace!(target: "dkg", "Will skip passing message to state machine since sender is self");
 					Ok(None)
 				}
 			},
 
 			(_l, _r) => {
-				// log::warn!("Received message for mixed stage: Local: {:?}, payload: {:?}", l, r);
+				// dkg_logging::warn!("Received message for mixed stage: Local: {:?}, payload:
+				// {:?}", l, r);
 				Ok(None)
 			},
 		}
@@ -119,12 +120,12 @@ where
 					Ok(None) => continue,
 
 					Err(err) => {
-						log::warn!(target: "dkg", "While mapping signed message, received an error: {:?}", err);
+						dkg_logging::warn!(target: "dkg", "While mapping signed message, received an error: {:?}", err);
 						continue
 					},
 				},
 				Some(Err(err)) => {
-					log::error!(target: "dkg", "Stream RECV error: {:?}", err);
+					dkg_logging::error!(target: "dkg", "Stream RECV error: {:?}", err);
 					continue
 				},
 				None => return Poll::Ready(None),

dkg-gadget/src/async_protocols/keygen/handler.rs

@@ -51,7 +51,7 @@ where
 		let protocol = async move {
 			let (keygen_id, ..) = get_party_session_id(&params);
 			if let Some(keygen_id) = keygen_id {
-				log::info!(target: "dkg_gadget::keygen", "Will execute keygen since local is in best authority set");
+				dkg_logging::info!(target: "dkg_gadget::keygen", "Will execute keygen since local is in best authority set");
 				let t = threshold;
 				let n = params.best_authorities.len() as u16;
 				// wait for the start signal
@@ -62,9 +62,9 @@ where
 				params.handle.set_status(MetaHandlerStatus::Keygen);
 				// Execute the keygen
 				GenericAsyncHandler::new_keygen(params, keygen_id, t, n, status)?.await?;
-				log::debug!(target: "dkg_gadget::keygen", "Keygen stage complete!");
+				dkg_logging::debug!(target: "dkg_gadget::keygen", "Keygen stage complete!");
 			} else {
-				log::info!(target: "dkg_gadget::keygen", "Will skip keygen since local is NOT in best authority set");
+				dkg_logging::info!(target: "dkg_gadget::keygen", "Will skip keygen since local is NOT in best authority set");
 			}
 
 			Ok(())
@@ -74,11 +74,11 @@ where
 				Ok(_) => {
 					// Set the status as complete.
 					status_handle.set_status(MetaHandlerStatus::Complete);
-					log::info!(target: "dkg_gadget::keygen", "🕸️  Keygen GenericAsyncHandler completed");
+					dkg_logging::info!(target: "dkg_gadget::keygen", "🕸️  Keygen GenericAsyncHandler completed");
 				}
 				Err(ref err) => {
 					// Do not update the status here, evetually the Keygen will fail and timeout.
-					log::error!(target: "dkg_gadget::keygen", "Keygen failed with error: {:?}", err);
+					dkg_logging::error!(target: "dkg_gadget::keygen", "Keygen failed with error: {:?}", err);
 				}
 			};
 			res
@@ -88,7 +88,7 @@ where
 			tokio::select! {
 				res0 = protocol => res0,
 				res1 = stop_rx.recv() => {
-					log::info!(target: "dkg_gadget::keygen", "Stopper has been called {:?}", res1);
+					dkg_logging::info!(target: "dkg_gadget::keygen", "Stopper has been called {:?}", res1);
 					Ok(())
 				}
 			}

dkg-gadget/src/async_protocols/keygen/state_machine.rs

@@ -39,30 +39,31 @@ impl StateMachineHandler for Keygen {
 		// Send the payload to the appropriate AsyncProtocols
 		match payload {
 			DKGMsgPayload::Keygen(msg) => {
-				log::info!(target: "dkg_gadget::async_protocol::keygen", "Handling Keygen inbound message from id={}, session={}", msg.sender_id, session_id);
-				let message: Msg<ProtocolMessage> =
-					match serde_json::from_slice(msg.keygen_msg.as_slice()) {
-						Ok(message) => message,
-						Err(err) => {
-							log::error!(target: "dkg_gadget::async_protocol::keygen", "Error deserializing message: {}", err);
-							// Skip this message.
-							return Ok(())
-						},
-					};
+				dkg_logging::info!(target: "dkg_gadget::async_protocol::keygen", "Handling Keygen inbound message from id={}, session={}", msg.sender_id, session_id);
+				let message: Msg<ProtocolMessage> = match serde_json::from_slice(
+					msg.keygen_msg.as_slice(),
+				) {
+					Ok(message) => message,
+					Err(err) => {
+						dkg_logging::error!(target: "dkg_gadget::async_protocol::keygen", "Error deserializing message: {}", err);
+						// Skip this message.
+						return Ok(())
+					},
+				};
 
 				if let Some(recv) = message.receiver.as_ref() {
 					if *recv != local_ty.get_i() {
-						log::info!("Skipping passing of message to async proto since not intended for local");
+						dkg_logging::info!("Skipping passing of message to async proto since not intended for local");
 						return Ok(())
 					}
 				}
 				if let Err(e) = to_async_proto.unbounded_send(message) {
-					log::error!(target: "dkg_gadget::async_protocol::keygen", "Error sending message to async proto: {}", e);
+					dkg_logging::error!(target: "dkg_gadget::async_protocol::keygen", "Error sending message to async proto: {}", e);
 				}
 			},
 
 			err =>
-				log::debug!(target: "dkg_gadget::async_protocol::keygen", "Invalid payload received: {:?}", err),
+				dkg_logging::debug!(target: "dkg_gadget::async_protocol::keygen", "Invalid payload received: {:?}", err),
 		}
 
 		Ok(())
@@ -74,7 +75,7 @@ impl StateMachineHandler for Keygen {
 		_: Self::AdditionalReturnParam,
 		_: u8,
 	) -> Result<<Self as StateMachine>::Output, DKGError> {
-		log::info!(target: "dkg_gadget::async_protocol::keygen", "Completed keygen stage successfully!");
+		dkg_logging::info!(target: "dkg_gadget::async_protocol::keygen", "Completed keygen stage successfully!");
 		// PublicKeyGossip (we need meta handler to handle this)
 		// when keygen finishes, we gossip the signed key to peers.
 		// [1] create the message, call the "public key gossip" in