Add trace-level logging via the log facade

We recently stumbled across some harder to debug issues that highlighted
that the absence of logging in `vss-client-ng` can be a pain. Therefore,
we here introduce logging for requests and the retry logic based on the
`log` facade, which not only allows the logging to easily integrate with
the Rust ecosystem, but is also a non-API breaking change allowing us to
ship this in a patch release.

Author: tnull

Cargo.toml

@@ -31,6 +31,7 @@ serde_json = { version = "1.0.113", default-features = false, optional = true }
 
 bitcoin_hashes = "0.14.0"
 chacha20-poly1305 = "0.1.2"
+log = { version = "0.4.29", default-features = false, features = ["std"]}
 
 [target.'cfg(genproto)'.build-dependencies]
 prost-build = { version = "0.11.3" }

src/client.rs

@@ -5,13 +5,16 @@ use std::collections::HashMap;
 use std::default::Default;
 use std::sync::Arc;
 
+use log::trace;
+
 use crate::error::VssError;
 use crate::headers::{get_headermap, FixedHeaders, VssHeaderProvider};
 use crate::types::{
 	DeleteObjectRequest, DeleteObjectResponse, GetObjectRequest, GetObjectResponse,
 	ListKeyVersionsRequest, ListKeyVersionsResponse, PutObjectRequest, PutObjectResponse,
 };
 use crate::util::retry::{retry, RetryPolicy};
+use crate::util::KeyValueVecKeyPrinter;
 
 const APPLICATION_OCTET_STREAM: &str = "application/octet-stream";
 const DEFAULT_TIMEOUT: std::time::Duration = std::time::Duration::from_secs(10);
@@ -77,7 +80,9 @@ impl<R: RetryPolicy<E = VssError>> VssClient<R> {
 	pub async fn get_object(
 		&self, request: &GetObjectRequest,
 	) -> Result<GetObjectResponse, VssError> {
-		retry(
+		let request_id: u64 = rand::random();
+		trace!("Sending GetObjectRequest {} for key {}.", request_id, request.key);
+		let res = retry(
 			|| async {
 				let url = format!("{}/getObject", self.base_url);
 				self.post_request(request, &url).await.and_then(|response: GetObjectResponse| {
@@ -92,7 +97,11 @@ impl<R: RetryPolicy<E = VssError>> VssClient<R> {
 			},
 			&self.retry_policy,
 		)
-		.await
+		.await;
+		if let Err(ref e) = res {
+			trace!("GetObjectRequest {} failed: {}", request_id, e);
+		}
+		res
 	}
 
 	/// Writes multiple [`PutObjectRequest::transaction_items`] as part of a single transaction.
@@ -102,14 +111,25 @@ impl<R: RetryPolicy<E = VssError>> VssClient<R> {
 	pub async fn put_object(
 		&self, request: &PutObjectRequest,
 	) -> Result<PutObjectResponse, VssError> {
-		retry(
+		let request_id: u64 = rand::random();
+		trace!(
+			"Sending PutObjectRequest {} for transaction_items {} and delete_items {}.",
+			request_id,
+			KeyValueVecKeyPrinter(&request.transaction_items),
+			KeyValueVecKeyPrinter(&request.delete_items),
+		);
+		let res = retry(
 			|| async {
 				let url = format!("{}/putObjects", self.base_url);
 				self.post_request(request, &url).await
 			},
 			&self.retry_policy,
 		)
-		.await
+		.await;
+		if let Err(ref e) = res {
+			trace!("PutObjectRequest {} failed: {}", request_id, e);
+		}
+		res
 	}
 
 	/// Deletes the given `key` and `value` in `request`.
@@ -118,14 +138,24 @@ impl<R: RetryPolicy<E = VssError>> VssClient<R> {
 	pub async fn delete_object(
 		&self, request: &DeleteObjectRequest,
 	) -> Result<DeleteObjectResponse, VssError> {
-		retry(
+		let request_id: u64 = rand::random();
+		trace!(
+			"Sending DeleteObjectRequest {} for key {:?}",
+			request_id,
+			request.key_value.iter().map(|t| &t.key)
+		);
+		let res = retry(
 			|| async {
 				let url = format!("{}/deleteObject", self.base_url);
 				self.post_request(request, &url).await
 			},
 			&self.retry_policy,
 		)
-		.await
+		.await;
+		if let Err(ref e) = res {
+			trace!("DeleteObjectRequest {} failed: {}", request_id, e);
+		}
+		res
 	}
 
 	/// Lists keys and their corresponding version for a given [`ListKeyVersionsRequest::store_id`].
@@ -134,14 +164,26 @@ impl<R: RetryPolicy<E = VssError>> VssClient<R> {
 	pub async fn list_key_versions(
 		&self, request: &ListKeyVersionsRequest,
 	) -> Result<ListKeyVersionsResponse, VssError> {
-		retry(
+		let request_id: u64 = rand::random();
+		trace!(
+			"Sending ListKeyVersionsRequest {} for key_prefix {:?}, page_size {:?}, page_token {:?}",
+			request_id,
+			request.key_prefix,
+			request.page_size,
+			request.page_token
+		);
+		let res = retry(
 			|| async {
 				let url = format!("{}/listKeyVersions", self.base_url);
 				self.post_request(request, &url).await
 			},
 			&self.retry_policy,
 		)
-		.await
+		.await;
+		if let Err(ref e) = res {
+			trace!("ListKeyVersionsRequest {} failed: {}", request_id, e);
+		}
+		res
 	}
 
 	async fn post_request<Rq: Message, Rs: Message + Default>(

src/util/mod.rs

@@ -1,3 +1,6 @@
+use crate::types::KeyValue;
+use core::fmt;
+
 /// Contains [`StorableBuilder`] utility.
 ///
 /// [`StorableBuilder`]: storable_builder::StorableBuilder
@@ -10,3 +13,20 @@ pub mod retry;
 ///
 /// [`KeyObfuscator`]: key_obfuscator::KeyObfuscator
 pub mod key_obfuscator;
+
+pub(crate) struct KeyValueVecKeyPrinter<'a>(pub(crate) &'a Vec<KeyValue>);
+
+impl fmt::Display for KeyValueVecKeyPrinter<'_> {
+	fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+		write!(f, "[")?;
+		for (i, k) in self.0.iter().enumerate() {
+			if i == self.0.len() - 1 {
+				write!(f, "{}", &k.key)?;
+			} else {
+				write!(f, "{}, ", &k.key)?;
+			}
+		}
+		write!(f, "]")?;
+		Ok(())
+	}
+}

src/util/retry.rs

@@ -4,6 +4,8 @@ use std::future::Future;
 use std::marker::PhantomData;
 use std::time::Duration;
 
+use log::trace;
+
 /// A function that performs and retries the given operation according to a retry policy.
 ///
 /// **Caution**: A retry policy without the number of attempts capped by [`MaxAttemptsRetryPolicy`]
@@ -69,6 +71,12 @@ where
 					accumulated_delay,
 					error: &err,
 				}) {
+					trace!(
+						"Operation failed on attempt {}, retrying in {}ms: {}",
+						attempts_made,
+						delay.as_millis(),
+						err
+					);
 					tokio::time::sleep(delay).await;
 					accumulated_delay += delay;
 				} else {