Skip to content

Add trace-level logging via the log facade #51

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
tnull wants to merge 1 commit into
base: main
Choose a base branch
from
Open

Add trace-level logging via the log facade #51

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"]}
Copy link

@TheBlueMatt TheBlueMatt Dec 17, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Seems fine for now given its already in the transitive dep set, but post-#52 it presumably won't be and we'll have to revert this. What's the plan after that?

Copy link
Contributor Author

@tnull tnull Dec 17, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well, the log facade is the default for logging across most Rust crates. So we might actually want to consider adding (optional) log-based logging support to bitreq as otherwise we will lose a lot of insight when making the switch.

FWIW, before we integrated it in LDK Node, we had multiple users entirely confused why LDK Node logs were absent from their logs, until their realized we did something custom that didn't have the expected compatibility what ~every other project does. While I agree that we should be cautious with additional dependencies, sharing a usable and expected interface is important. So taking a dependency on log seems entirely worth for me, especially, if we, as we now did in lightningdevkit/ldk-server#76, don't take additional dependencies for the actual default consumer.

IMO, across projects we could also eventually consider taking a similar path w.r.t tracing: we could just take a dependency on tracing_core and (re-)implement the rest ourselves.

Copy link

@TheBlueMatt TheBlueMatt Dec 17, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IMO, across projects we could also eventually consider taking a similar path w.r.t tracing: we could just take a dependency on tracing_core and (re-)implement the rest ourselves.

I think you just undercut your argument around log being the way that we have to do logging here :). Many things use log, but not everything, with tokio pushing tracing instead its certainly not universal. Having optional dependencies on log/tracing, of course, is perfectly reasonable, but ultimately when we support both we'll need some kind of unified underlying logging interface again...


[target.'cfg(genproto)'.build-dependencies]
prost-build = { version = "0.11.3" }
Expand Down
58 changes: 50 additions & 8 deletions src/client.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Copy link
Contributor

@tankyleo tankyleo Dec 19, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In the happy case do we want a confirmation that the operation was successful ? I would expect to see one myself, but I may get used to "silence" == success.

let res = retry(
|| async {
let url = format!("{}/getObject", self.base_url);
self.post_request(request, &url).await.and_then(|response: GetObjectResponse| {
Expand All @@ -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.
Expand All @@ -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`.
Expand All @@ -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`].
Expand All @@ -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>(
Expand Down
20 changes: 20 additions & 0 deletions src/util/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,3 +1,6 @@
use crate::types::KeyValue;
use core::fmt;

/// Contains [`StorableBuilder`] utility.
///
/// [`StorableBuilder`]: storable_builder::StorableBuilder
Expand All @@ -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(())
}
}
8 changes: 8 additions & 0 deletions src/util/retry.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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`]
Expand Down Expand Up @@ -69,6 +71,12 @@ where
accumulated_delay,
error: &err,
}) {
trace!(
"Operation failed on attempt {}, retrying in {}ms: {}",
Copy link
Contributor

@tankyleo tankyleo Dec 19, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

May not be necessary because once we've exhausted all attempts, we do log the request_id with the final failure message, but wondering if we want it here too.

attempts_made,
delay.as_millis(),
err
);
tokio::time::sleep(delay).await;
accumulated_delay += delay;
} else {
Expand Down