feat: add logging to DIP components (#630)

Fixes KILTprotocol/ticket#3128.

I introduced different new logging targets. For the deposit storage and
relay store pallet, which are not technically part of the DIP protocol,
the target is a standalone one. For the other things, meaning DIP
pallets and DIP provider/consumer components, the log targets have the
following structure: `"dip::<provider>|<consumer>::<type_name>"`. So
filtering provider logs would require `RUST_LOG=dip::provider=info`, for
instance. Most of the logs are `info` level, with some `error` where we
return `Internal` errors or errors coalesced into a `u8` value, and a
couple of `trace` for the less important stuff to show.

Author: ntn-x2

Cargo.lock

@@ -209,7 +209,7 @@ impl<
 		ensure!(!signing_leaves_indices.is_empty(), Error::InvalidDidKeyRevealed);
 
 		let signing_leaves_indices_vector = signing_leaves_indices.try_into().map_err(|_| {
-			log::error!("Should never fail to convert vector of signing leaf indices into BoundedVec.");
+			log::error!(target: "dip::consumer::DipRevealedDetailsAndVerifiedDidSignatureFreshnessV0", "Failed to convert vector of signing leaf indices into BoundedVec<u8, {MAX_REVEALED_LEAVES_COUNT}>.");
 			Error::Internal
 		})?;
 

crates/kilt-dip-primitives/src/merkle_proofs/v0/dip_subject_state/mod.rs

@@ -97,17 +97,29 @@ impl<
 	/// `Error::Internal` which, anyway, should never happen.
 	pub fn get_signing_leaves(
 		&self,
-	) -> Result<impl Iterator<Item = &RevealedDidKey<KiltDidKeyId, KiltBlockNumber, KiltAccountId>>, Error> {
+	) -> Result<impl Iterator<Item = &RevealedDidKey<KiltDidKeyId, KiltBlockNumber, KiltAccountId>>, Error>
+	where
+		KiltDidKeyId: Debug,
+		KiltBlockNumber: Debug,
+		KiltAccountId: Debug,
+		KiltWeb3Name: Debug,
+		KiltLinkableAccountId: Debug,
+	{
+		const LOG_TARGET: &str = "dip::consumer::DipOriginInfoV0";
 		let leaves = self
 			.signing_leaves_indices
 			.iter()
 			.map(|index| {
 				let leaf = self.revealed_leaves.get(usize::saturated_from(*index)).ok_or_else(|| {
-					log::error!("Should never fail to retrieve the signing leaf at index {:#?}.", index);
+					log::error!(
+						target: LOG_TARGET,
+						"Failed to retrieve the signing leaf at index {:#?}.",
+						index
+					);
 					Error::Internal
 				})?;
 				let RevealedDidMerkleProofLeaf::DidKey(did_key) = leaf else {
-					log::error!("Should never fail to convert the signing leaf to a DID Key leaf.");
+					log::error!(target: LOG_TARGET, "Failed to convert the signing leaf {:#?} to a DID Key leaf.", leaf);
 					return Err(Error::Internal);
 				};
 				Ok(did_key)

crates/kilt-dip-primitives/src/merkle_proofs/v0/output_common.rs

@@ -176,6 +176,7 @@ impl<
 		ProviderHeader: Decode + HeaderT<Hash = OutputOf<RelayHasher>, Number = KiltBlockNumber>,
 	{
 		let provider_head_storage_key = calculate_parachain_head_storage_key(provider_para_id);
+		log::trace!(target: "dip::consumer::ParachainDipDidProofV0", "Calculated storage key for para ID {:#?} = {:#?}", provider_para_id, provider_head_storage_key);
 		// TODO: Figure out why RPC call returns 2 bytes in front which we don't need
 		//This could be the reason (and the solution): https://substrate.stackexchange.com/a/1891/1795
 		let provider_header = verify_storage_value_proof_with_decoder::<_, RelayHasher, ProviderHeader>(
@@ -323,6 +324,7 @@ impl<
 	{
 		let dip_commitment_storage_key =
 			calculate_dip_identity_commitment_storage_key_for_runtime::<ProviderRuntime>(subject, 0);
+		log::trace!(target: "dip::consumer::DipDidProofWithVerifiedStateRootV0", "Calculated storage key for subject {:#?} = {:#?}", subject, dip_commitment_storage_key);
 		let dip_commitment = verify_storage_value_proof::<_, ParachainHasher, IdentityCommitmentOf<ProviderRuntime>>(
 			&dip_commitment_storage_key,
 			self.state_root,
@@ -466,10 +468,11 @@ impl<
 			self.dip_proof.blinded.as_slice(),
 			proof_leaves_key_value_pairs.as_slice(),
 		)
+		// Can't log since the result returned by `verify_trie_proof` implements `Debug` only with `std`.
 		.map_err(|_| Error::InvalidDidMerkleProof)?;
 
 		let revealed_leaves = BoundedVec::try_from(self.dip_proof.revealed).map_err(|_| {
-			log::error!("Should not fail to construct BoundedVec since bounds were checked before.");
+			log::error!(target: "dip::consumer::DipDidProofWithVerifiedSubjectCommitmentV0", "Failed to construct BoundedVec<u8, {MAX_REVEALED_LEAVES_COUNT}>.");
 			Error::Internal
 		})?;
 

crates/kilt-dip-primitives/src/merkle_proofs/v0/provider_state/mod.rs

@@ -76,9 +76,17 @@ where
 	MerkleHasher: Hash,
 	OutputOf<MerkleHasher>: Ord,
 {
+	const LOG_TARGET: &str = "dip::consumer::verify_storage_value_proof_with_decoder";
 	let storage_proof = StorageProof::new(state_proof);
 	let mut revealed_leaves = read_proof_check::<MerkleHasher, _>(state_root, storage_proof, [storage_key].iter())
-		.map_err(|_| MerkleProofError::InvalidProof)?;
+		.map_err(|e| {
+			log::info!(
+				target: LOG_TARGET,
+				"Failed verification of storage proof with error {:#?}",
+				e
+			);
+			MerkleProofError::InvalidProof
+		})?;
 
 	debug_assert!(
 		revealed_leaves.len() == 1usize,

crates/kilt-dip-primitives/src/state_proofs/mod.rs

@@ -16,6 +16,9 @@
 
 // If you feel like getting in touch with us, you can do so at [email protected]
 
+use sp_std::fmt::Debug;
+
+#[derive(Debug)]
 #[repr(u8)]
 pub(crate) enum DipProofComponentTooLargeError {
 	ParachainHeadProofTooManyLeaves = 0,

crates/kilt-dip-primitives/src/verifier/errors.rs

@@ -188,12 +188,12 @@ impl<
 	KiltRuntime::IdentityCommitmentGenerator:
 		IdentityCommitmentGenerator<KiltRuntime, Output = RelaychainRuntime::Hash>,
 	SignedExtra: GetWithoutArg,
-	SignedExtra::Result: Encode,
+	SignedExtra::Result: Encode + Debug,
 	DidCallVerifier: DipCallOriginFilter<
 		RuntimeCallOf<ConsumerRuntime>,
 		OriginInfo = Vec<RevealedDidKey<KeyIdOf<KiltRuntime>, BlockNumberFor<KiltRuntime>, KiltRuntime::AccountId>>,
 	>,
-	DidCallVerifier::Error: Into<u8>,
+	DidCallVerifier::Error: Into<u8> + Debug,
 {
 	type Error = DipParachainStateProofVerifierError<DidCallVerifier::Error>;
 	type Proof = VersionedDipParachainStateProof<